-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Tue 2024-07-23 10:43:04 CEST. -- Jul 23 10:42:08 volumio-principal ntpd[653]: Soliciting pool server 2606:4700:f1::1 Jul 23 10:42:11 volumio-principal wpa_supplicant[758]: wlan0: Associated with b8:be:f4:bc:78:d5 Jul 23 10:42:11 volumio-principal dhcpcd[770]: wlan0: carrier lost Jul 23 10:42:11 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:be:f4:bc:78:d5 completed [id=0 id_str=] Jul 23 10:42:11 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jul 23 10:42:11 volumio-principal avahi-daemon[516]: Withdrawing address record for 169.254.176.174 on wlan0. Jul 23 10:42:11 volumio-principal avahi-daemon[516]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 169.254.176.174. Jul 23 10:42:11 volumio-principal avahi-daemon[516]: Interface wlan0.IPv4 no longer relevant for mDNS. Jul 23 10:42:11 volumio-principal dhcpcd[770]: wlan0: deleting route to 169.254.0.0/16 Jul 23 10:42:11 volumio-principal dhcpcd[770]: wlan0: deleting default route Jul 23 10:42:11 volumio-principal volumio[2302]: info: Discovery: A device disappeared from network Jul 23 10:42:11 volumio-principal volumio[2302]: info: Discovery: A device disappeared from network Jul 23 10:42:11 volumio-principal dhcpcd[770]: wlan0: carrier acquired Jul 23 10:42:11 volumio-principal dhcpcd[770]: wlan0: IAID dd:80:f5:90 Jul 23 10:42:11 volumio-principal dhcpcd[770]: wlan0: soliciting a DHCP lease Jul 23 10:42:12 volumio-principal dhcpcd[770]: wlan0: soliciting an IPv6 router Jul 23 10:42:12 volumio-principal dhcpcd[770]: wlan0: offered 192.168.100.125 from 192.168.100.1 Jul 23 10:42:13 volumio-principal dhcpcd[770]: wlan0: probing address 192.168.100.125/24 Jul 23 10:42:13 volumio-principal ntpd[653]: Soliciting pool server 82.223.203.159 Jul 23 10:42:13 volumio-principal ntpd[653]: Deleting interface #6 wlan0, 169.254.176.174#123, interface stats: received=0, sent=6, dropped=0, active_time=18 secs Jul 23 10:42:13 volumio-principal ntpd[653]: 194.0.5.123 local addr 169.254.176.174 -> Jul 23 10:42:13 volumio-principal ntpd[653]: 217.71.200.210 local addr 169.254.176.174 -> Jul 23 10:42:13 volumio-principal ntpd[653]: 193.149.0.217 local addr 169.254.176.174 -> Jul 23 10:42:13 volumio-principal ntpd[653]: 162.159.200.1 local addr 169.254.176.174 -> Jul 23 10:42:13 volumio-principal ntpd[653]: 193.149.0.221 local addr 169.254.176.174 -> Jul 23 10:42:13 volumio-principal ntpd[653]: 162.159.200.123 local addr 169.254.176.174 -> Jul 23 10:42:15 volumio-principal ntpd[653]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Jul 23 10:42:16 volumio-principal volumio[2302]: info: Discovery: Browse raised the following error Error: getaddrinfo -3008 Jul 23 10:42:18 volumio-principal dhcpcd[770]: wlan0: leased 192.168.100.125 for 86400 seconds Jul 23 10:42:18 volumio-principal avahi-daemon[516]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.100.125. Jul 23 10:42:18 volumio-principal avahi-daemon[516]: New relevant interface wlan0.IPv4 for mDNS. Jul 23 10:42:18 volumio-principal dhcpcd[770]: wlan0: adding route to 192.168.100.0/24 Jul 23 10:42:18 volumio-principal avahi-daemon[516]: Registering new address record for 192.168.100.125 on wlan0.IPv4. Jul 23 10:42:18 volumio-principal dhcpcd[770]: wlan0: adding default route via 192.168.100.1 Jul 23 10:42:19 volumio-principal volumio[2302]: info: Discovery: Browse raised the following error Error: getaddrinfo -3008 Jul 23 10:42:19 volumio-principal volumio[2302]: info: Discovery: adding ac411f73-a670-4edb-803a-53cc23512fdf Jul 23 10:42:19 volumio-principal volumio[2302]: info: Discovery: Found device Volumio-Principal Jul 23 10:42:19 volumio-principal volumio[2302]: info: CoreCommandRouter::volumioGetState Jul 23 10:42:20 volumio-principal ntpd[653]: Listen normally on 7 wlan0 192.168.100.125:123 Jul 23 10:42:20 volumio-principal ntpd[653]: new interface(s) found: waking up resolver Jul 23 10:42:21 volumio-principal ntpd[653]: Soliciting pool server 208.85.20.220 Jul 23 10:42:22 volumio-principal ntpd[653]: Soliciting pool server 158.227.98.15 Jul 23 10:42:23 volumio-principal ntpd[653]: Soliciting pool server 5.250.191.170 Jul 23 10:42:24 volumio-principal ntpd[653]: Soliciting pool server 90.68.206.60 Jul 23 10:42:28 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:be:f4:bc:78:d5 reason=8 Jul 23 10:42:28 volumio-principal dhcpcd[770]: wlan0: carrier lost Jul 23 10:42:28 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Jul 23 10:42:28 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=US Jul 23 10:42:28 volumio-principal avahi-daemon[516]: Withdrawing address record for 192.168.100.125 on wlan0. Jul 23 10:42:28 volumio-principal avahi-daemon[516]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.100.125. Jul 23 10:42:28 volumio-principal avahi-daemon[516]: Interface wlan0.IPv4 no longer relevant for mDNS. Jul 23 10:42:28 volumio-principal dhcpcd[770]: wlan0: deleting route to 192.168.100.0/24 Jul 23 10:42:28 volumio-principal dhcpcd[770]: wlan0: deleting default route via 192.168.100.1 Jul 23 10:42:28 volumio-principal volumio[2302]: info: Discovery: A device disappeared from network Jul 23 10:42:28 volumio-principal volumio[2302]: info: Discovery: Device volumio-principal disappeared from network Jul 23 10:42:28 volumio-principal wpa_supplicant[758]: wlan0: Trying to associate with SSID 'devolo-961' Jul 23 10:42:28 volumio-principal volumio[2302]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:28 volumio-principal volumio[2302]: Error: send ENETUNREACH 255.255.255.255:3483 Jul 23 10:42:28 volumio-principal volumio[2302]: at doSend (dgram.js:692:16) Jul 23 10:42:28 volumio-principal volumio[2302]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Jul 23 10:42:28 volumio-principal volumio[2302]: at afterDns (dgram.js:638:5) Jul 23 10:42:28 volumio-principal volumio[2302]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Jul 23 10:42:28 volumio-principal volumio[2302]: errno: -101, Jul 23 10:42:28 volumio-principal volumio[2302]: code: 'ENETUNREACH', Jul 23 10:42:28 volumio-principal volumio[2302]: syscall: 'send', Jul 23 10:42:28 volumio-principal volumio[2302]: address: '255.255.255.255', Jul 23 10:42:28 volumio-principal volumio[2302]: port: 3483 Jul 23 10:42:28 volumio-principal volumio[2302]: } Jul 23 10:42:28 volumio-principal volumio[2302]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:29 volumio-principal sudo[3020]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-23 10:41 Jul 23 10:42:29 volumio-principal sudo[3020]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:29 volumio-principal sudo[3020]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:29 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:29] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jul 23 10:42:29 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:29] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jul 23 10:42:29 volumio-principal go-librespot[2709]: time="2024-07-23T10:42:29+02:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Jul 23 10:42:29 volumio-principal systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:29 volumio-principal systemd[1]: volumio.service: Failed with result 'exit-code'. Jul 23 10:42:29 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:29 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:29 volumio-principal systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Jul 23 10:42:29 volumio-principal systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7. Jul 23 10:42:29 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:29 volumio-principal systemd[1]: Stopped Volumio Backend Module. Jul 23 10:42:29 volumio-principal systemd[1]: Started Volumio Backend Module. Jul 23 10:42:29 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:30 volumio-principal ntpd[653]: Deleting interface #7 wlan0, 192.168.100.125#123, interface stats: received=16, sent=23, dropped=5, active_time=10 secs Jul 23 10:42:30 volumio-principal ntpd[653]: 5.250.191.170 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 158.227.98.15 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 208.85.20.220 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 194.0.5.123 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 217.71.200.210 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 193.149.0.217 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 162.159.200.1 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 193.149.0.221 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal ntpd[653]: 162.159.200.123 local addr 192.168.100.125 -> Jul 23 10:42:30 volumio-principal volumio[3034]: info: ------------------------------------------- Jul 23 10:42:30 volumio-principal volumio[3034]: info: ----- Volumio3 ---- Jul 23 10:42:30 volumio-principal volumio[3034]: info: ------------------------------------------- Jul 23 10:42:30 volumio-principal volumio[3034]: info: ----- System startup ---- Jul 23 10:42:30 volumio-principal volumio[3034]: info: ------------------------------------------- Jul 23 10:42:31 volumio-principal volumio[3034]: info: MYVOLUMIO Environment detected Jul 23 10:42:31 volumio-principal volumio[3034]: info: Plugin folders cleanup Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning into folder /volumio/app/plugins/ Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning category audio_interface Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning category miscellanea Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning category music_service Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning category plugins.json Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning category system_controller Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning category user_interface Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning into folder /data/plugins/ Jul 23 10:42:31 volumio-principal volumio[3034]: info: Scanning category music_service Jul 23 10:42:31 volumio-principal volumio[3034]: info: Plugin folders cleanup completed Jul 23 10:42:31 volumio-principal volumio[3034]: info: ------------------------------------------- Jul 23 10:42:31 volumio-principal volumio[3034]: info: ----- Core plugins startup ---- Jul 23 10:42:31 volumio-principal volumio[3034]: info: ------------------------------------------- Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugins from folder /volumio/app/plugins/ Jul 23 10:42:31 volumio-principal volumio[3034]: info: Adding plugin upnp to MyMusic Plugins Jul 23 10:42:31 volumio-principal volumio[3034]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 23 10:42:31 volumio-principal volumio[3034]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugins from folder /data/plugins/ Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "system"... Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "appearance"... Jul 23 10:42:31 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "network"... Jul 23 10:42:31 volumio-principal volumio[3034]: info: Refreshing Cached IP Addresses Jul 23 10:42:31 volumio-principal sudo[3057]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 23 10:42:31 volumio-principal sudo[3057]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:31 volumio-principal sudo[3057]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:31 volumio-principal sudo[3059]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 23 10:42:31 volumio-principal sudo[3059]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "services"... Jul 23 10:42:31 volumio-principal sudo[3059]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "alsa_controller"... Jul 23 10:42:31 volumio-principal sudo[3063]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jul 23 10:42:31 volumio-principal sudo[3063]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:31 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "wizard"... Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "volumio_command_line_client"... Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "upnp"... Jul 23 10:42:31 volumio-principal volumio[3034]: info: [1721724151825] Starting Upmpd Daemon Jul 23 10:42:31 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "my_music"... Jul 23 10:42:31 volumio-principal volumio[3034]: info: Loading plugin "mpd"... Jul 23 10:42:32 volumio-principal volumio[3034]: info: Creating MPD Configuration file Jul 23 10:42:32 volumio-principal sudo[3070]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "upnp_browser"... Jul 23 10:42:32 volumio-principal sudo[3070]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:32 volumio-principal sudo[3070]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:32 volumio-principal sudo[3072]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:42:32 volumio-principal sudo[3072]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:32 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:42:32 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:42:32 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:42:32 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "networkfs"... Jul 23 10:42:32 volumio-principal volumio[3034]: info: Starting Udev Watcher for removable devices Jul 23 10:42:32 volumio-principal volumio[3034]: info: Ignoring mount for partition: boot Jul 23 10:42:32 volumio-principal volumio[3034]: info: Ignoring mount for partition: volumio Jul 23 10:42:32 volumio-principal volumio[3034]: info: Ignoring mount for partition: volumio_data Jul 23 10:42:32 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "alarm-clock"... Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "airplay_emulation"... Jul 23 10:42:32 volumio-principal volumio[3034]: info: Starting Shairport Sync Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "last_100"... Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "webradio"... Jul 23 10:42:32 volumio-principal mpd[3077]: Jul 23 10:42 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:42:32 volumio-principal mpd[3077]: Jul 23 10:42 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:42:32 volumio-principal mpd[3077]: Jul 23 10:42 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "i2s_dacs"... Jul 23 10:42:32 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:42:32 volumio-principal sudo[3072]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "volumiodiscovery"... Jul 23 10:42:32 volumio-principal volumio[3034]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:32 volumio-principal volumio[3034]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:32 volumio-principal volumio[3034]: *** WARNING *** For more information see Jul 23 10:42:32 volumio-principal node[3034]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:32 volumio-principal volumio[3034]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:32 volumio-principal volumio[3034]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:32 volumio-principal volumio[3034]: *** WARNING *** For more information see Jul 23 10:42:32 volumio-principal node[3034]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:32 volumio-principal node[3034]: *** WARNING *** For more information see Jul 23 10:42:32 volumio-principal node[3034]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:32 volumio-principal node[3034]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:32 volumio-principal node[3034]: *** WARNING *** For more information see Jul 23 10:42:32 volumio-principal volumio[3034]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 23 10:42:32 volumio-principal volumio[3034]: info: Discovery: Started advertising with name: Volumio-Principal Jul 23 10:42:32 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:32 volumio-principal volumio[3034]: info: Loading plugin "spop"... Jul 23 10:42:33 volumio-principal volumio[3034]: info: Loading plugin "squeezelite_mc"... Jul 23 10:42:33 volumio-principal volumio[3034]: info: Loading plugin "outputs"... Jul 23 10:42:33 volumio-principal volumio[3034]: info: Loading plugin "albumart"... Jul 23 10:42:33 volumio-principal volumio[3034]: info: Plugin example_plugin is not enabled Jul 23 10:42:33 volumio-principal volumio[3034]: info: Loading plugin "inputs"... Jul 23 10:42:33 volumio-principal volumio[3034]: info: Loading plugin "updater_comm"... Jul 23 10:42:34 volumio-principal volumio[3034]: info: Plugin mpdemulation is not enabled Jul 23 10:42:34 volumio-principal volumio[3034]: info: Loading plugin "rest_api"... Jul 23 10:42:34 volumio-principal volumio[3034]: info: Loading plugin "websocket"... Jul 23 10:42:34 volumio-principal volumio[3034]: info: Loading plugin "lms"... Jul 23 10:42:34 volumio-principal volumio[3034]: info: Loading i18n strings for locale es Jul 23 10:42:34 volumio-principal volumio[3034]: Updating browse sources language Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:34 volumio-principal volumio[3034]: Forking 3 albumart workers Jul 23 10:42:34 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:34] [connect] Successful connection Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::initPlayerControls Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: Express server listening on port 3000 Jul 23 10:42:34 volumio-principal volumio[3034]: [Metrics] WebUI: 4s 66.85ms Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::resetVolumioState Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::getcurrentVolume Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:34 volumio-principal volumio[3034]: info: MPD Permissions set Jul 23 10:42:34 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:34] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1721724154 101 Jul 23 10:42:34 volumio-principal volumio[3034]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Jul 23 10:42:34 volumio-principal volumio[3034]: info: MPD running with PID3077 Jul 23 10:42:34 volumio-principal volumio[3034]: ,establishing connection Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: Reloading queue from file Jul 23 10:42:34 volumio-principal volumio[3034]: error: updateQueue error: null Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::setRepeat null single undefined Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::pushState Jul 23 10:42:34 volumio-principal volumio[3034]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::setRandom null Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::pushState Jul 23 10:42:34 volumio-principal volumio[3034]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:34 volumio-principal volumio[3034]: info: Setting Device type: Raspberry PI Jul 23 10:42:34 volumio-principal volumio[3034]: info: Completed loading Core Plugins Jul 23 10:42:34 volumio-principal volumio[3034]: info: Preparing to generate the ALSA configuration file Jul 23 10:42:34 volumio-principal volumio[3034]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::pushState Jul 23 10:42:34 volumio-principal volumio[3034]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreStateMachine::updateTrackBlock Jul 23 10:42:34 volumio-principal volumio[3034]: info: CorePlayQueue::getTrackBlock Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:34 volumio-principal volumio[3034]: error: updateQueue error: null Jul 23 10:42:34 volumio-principal volumio[3034]: info: Asound.conf file unchanged, so no further update is needed Jul 23 10:42:34 volumio-principal volumio[3034]: info: Output device has changed, restarting MPD Jul 23 10:42:34 volumio-principal volumio[3034]: Starting albumart workers Jul 23 10:42:34 volumio-principal volumio[3034]: Starting albumart workers Jul 23 10:42:34 volumio-principal volumio[3034]: Starting albumart workers Jul 23 10:42:34 volumio-principal volumio[3034]: info: Output device has changed, restarting Shairport Sync Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:34 volumio-principal sudo[3129]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:42:34 volumio-principal sudo[3129]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:34 volumio-principal sudo[3129]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:34 volumio-principal sudo[3131]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:42:34 volumio-principal sudo[3131]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:34 volumio-principal volumio[3034]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:34 volumio-principal volumio[3034]: info: ___________ START PLUGINS ___________ Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:34 volumio-principal volumio[3034]: info: [1721724154965] CoreMusicLibrary::Adding element Media Servers Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:34 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:35 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:42:35 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:42:35 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:42:35 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:42:35 volumio-principal volumio[3034]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:35 volumio-principal volumio[3034]: info: [1721724155161] CoreMusicLibrary::Adding element Last_100 Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:35 volumio-principal volumio[3034]: info: [1721724155165] CoreMusicLibrary::Adding element Webradio Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:42:35 volumio-principal volumio[3034]: info: Creating Spotify config file Jul 23 10:42:35 volumio-principal volumio[3034]: info: [squeezelite_mc] Starting proxy server... Jul 23 10:42:35 volumio-principal volumio[3034]: info: Volumio Calling Home Jul 23 10:42:35 volumio-principal sudo[3162]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart logitechmediaserver Jul 23 10:42:35 volumio-principal sudo[3162]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:35 volumio-principal systemd[1]: Stopping Logitech Media Server Daemon... Jul 23 10:42:35 volumio-principal volumio[3034]: info: [squeezelite_mc] Proxy server started on port 44383 Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:35 volumio-principal volumio[3034]: Unhandled rejection Error: No sockets available, cannot start. Jul 23 10:42:35 volumio-principal volumio[3034]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Jul 23 10:42:35 volumio-principal volumio[3034]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Jul 23 10:42:35 volumio-principal volumio[3034]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Jul 23 10:42:35 volumio-principal volumio[3034]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Jul 23 10:42:35 volumio-principal volumio[3034]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Jul 23 10:42:35 volumio-principal volumio[3034]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Jul 23 10:42:35 volumio-principal volumio[3034]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Jul 23 10:42:35 volumio-principal volumio[3034]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Jul 23 10:42:35 volumio-principal volumio[3034]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Jul 23 10:42:35 volumio-principal volumio[3034]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Jul 23 10:42:35 volumio-principal volumio[3034]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Jul 23 10:42:35 volumio-principal volumio[3034]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Jul 23 10:42:35 volumio-principal volumio[3034]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Jul 23 10:42:35 volumio-principal volumio[3034]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Jul 23 10:42:35 volumio-principal volumio[3034]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Jul 23 10:42:35 volumio-principal volumio[3034]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jul 23 10:42:35 volumio-principal volumio[3034]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Jul 23 10:42:35 volumio-principal systemd[1]: logitechmediaserver.service: Succeeded. Jul 23 10:42:35 volumio-principal volumio[3034]: info: MPD Permissions set Jul 23 10:42:35 volumio-principal systemd[1]: Stopped Logitech Media Server Daemon. Jul 23 10:42:35 volumio-principal systemd[1]: Starting Logitech Media Server Daemon... Jul 23 10:42:35 volumio-principal systemd[1]: Started Logitech Media Server Daemon. Jul 23 10:42:35 volumio-principal sudo[3162]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:35 volumio-principal volumio[3034]: info: Spotify config file written Jul 23 10:42:35 volumio-principal sudo[3182]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 23 10:42:35 volumio-principal sudo[3182]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:35 volumio-principal volumio[3034]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Jul 23 10:42:35 volumio-principal volumio[3034]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreStateMachine::pushState Jul 23 10:42:35 volumio-principal volumio[3034]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:35 volumio-principal volumio[3034]: info: logitechmediaserver started Jul 23 10:42:35 volumio-principal systemd[1]: Stopping go-librespot Daemon... Jul 23 10:42:35 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jul 23 10:42:35 volumio-principal systemd[1]: go-librespot-daemon.service: Succeeded. Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:35 volumio-principal sudo[3182]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:35 volumio-principal go-librespot[3184]: Librespot-go daemon starting... Jul 23 10:42:35 volumio-principal go-librespot[3184]: time="2024-07-23T10:42:35+02:00" level=info msg="generated new device id: 11c7ca94c952a6ed7858fa0794301210e7f5517d" Jul 23 10:42:35 volumio-principal go-librespot[3184]: time="2024-07-23T10:42:35+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal go-librespot[3184]: time="2024-07-23T10:42:35+02: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" Jul 23 10:42:35 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:35 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:35 volumio-principal volumio[3034]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreStateMachine::pushState Jul 23 10:42:35 volumio-principal volumio[3034]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:35 volumio-principal volumio[3034]: info: [squeezelite_mc] Server discovery started Jul 23 10:42:35 volumio-principal volumio[3034]: info: [squeezelite_mc] Player finder started Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:35 volumio-principal volumio[3034]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Jul 23 10:42:35 volumio-principal volumio[3034]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:35 volumio-principal volumio[3034]: Error: send ENETUNREACH 255.255.255.255:3483 Jul 23 10:42:35 volumio-principal volumio[3034]: at doSend (dgram.js:692:16) Jul 23 10:42:35 volumio-principal volumio[3034]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Jul 23 10:42:35 volumio-principal volumio[3034]: at afterDns (dgram.js:638:5) Jul 23 10:42:35 volumio-principal volumio[3034]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Jul 23 10:42:35 volumio-principal volumio[3034]: errno: -101, Jul 23 10:42:35 volumio-principal volumio[3034]: code: 'ENETUNREACH', Jul 23 10:42:35 volumio-principal volumio[3034]: syscall: 'send', Jul 23 10:42:35 volumio-principal volumio[3034]: address: '255.255.255.255', Jul 23 10:42:35 volumio-principal volumio[3034]: port: 3483 Jul 23 10:42:35 volumio-principal volumio[3034]: } Jul 23 10:42:35 volumio-principal volumio[3034]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:35 volumio-principal mpd[3144]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:42:35 volumio-principal mpd[3144]: output: No 'audio_output' defined in config file Jul 23 10:42:35 volumio-principal mpd[3144]: output: Attempt to detect audio output device Jul 23 10:42:35 volumio-principal mpd[3144]: output: Attempting to detect a alsa audio device Jul 23 10:42:35 volumio-principal mpd[3144]: output: Successfully detected a alsa audio device Jul 23 10:42:35 volumio-principal mpd[3144]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:42:35 volumio-principal mpd[3144]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:42:35 volumio-principal mpd[3144]: zeroconf: No global port, disabling zeroconf Jul 23 10:42:36 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:42:36 volumio-principal sudo[3131]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:36 volumio-principal sudo[3208]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-23 10:41 Jul 23 10:42:36 volumio-principal sudo[3208]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:36 volumio-principal sudo[3208]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:36 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:36] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jul 23 10:42:36 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:36] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jul 23 10:42:36 volumio-principal systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:36 volumio-principal sudo[3063]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:36 volumio-principal systemd[1]: volumio.service: Failed with result 'exit-code'. Jul 23 10:42:36 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:36 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:36 volumio-principal systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Jul 23 10:42:36 volumio-principal systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8. Jul 23 10:42:36 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:36 volumio-principal systemd[1]: Stopped Volumio Backend Module. Jul 23 10:42:36 volumio-principal systemd[1]: Started Volumio Backend Module. Jul 23 10:42:36 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:37 volumio-principal wpa_supplicant[758]: wlan0: Trying to associate with SSID 'devolo-961' Jul 23 10:42:37 volumio-principal volumio[3222]: info: ------------------------------------------- Jul 23 10:42:37 volumio-principal volumio[3222]: info: ----- Volumio3 ---- Jul 23 10:42:37 volumio-principal volumio[3222]: info: ------------------------------------------- Jul 23 10:42:37 volumio-principal volumio[3222]: info: ----- System startup ---- Jul 23 10:42:37 volumio-principal volumio[3222]: info: ------------------------------------------- Jul 23 10:42:38 volumio-principal volumio[3222]: info: MYVOLUMIO Environment detected Jul 23 10:42:38 volumio-principal volumio[3222]: info: Plugin folders cleanup Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning into folder /volumio/app/plugins/ Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning category audio_interface Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning category miscellanea Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning category music_service Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning category plugins.json Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning category system_controller Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning category user_interface Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning into folder /data/plugins/ Jul 23 10:42:38 volumio-principal volumio[3222]: info: Scanning category music_service Jul 23 10:42:38 volumio-principal volumio[3222]: info: Plugin folders cleanup completed Jul 23 10:42:38 volumio-principal volumio[3222]: info: ------------------------------------------- Jul 23 10:42:38 volumio-principal volumio[3222]: info: ----- Core plugins startup ---- Jul 23 10:42:38 volumio-principal volumio[3222]: info: ------------------------------------------- Jul 23 10:42:38 volumio-principal volumio[3222]: info: Loading plugins from folder /volumio/app/plugins/ Jul 23 10:42:38 volumio-principal volumio[3222]: info: Adding plugin upnp to MyMusic Plugins Jul 23 10:42:38 volumio-principal volumio[3222]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 23 10:42:38 volumio-principal volumio[3222]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 23 10:42:38 volumio-principal volumio[3222]: info: Loading plugins from folder /data/plugins/ Jul 23 10:42:38 volumio-principal volumio[3222]: info: Loading plugin "system"... Jul 23 10:42:38 volumio-principal volumio[3222]: info: Loading plugin "appearance"... Jul 23 10:42:38 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:42:38 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jul 23 10:42:38 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:38 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:38 volumio-principal go-librespot[3244]: Librespot-go daemon starting... Jul 23 10:42:38 volumio-principal go-librespot[3244]: time="2024-07-23T10:42:38+02:00" level=info msg="generated new device id: 92d4bec9e60fb274095113ee2ef315a084865e09" Jul 23 10:42:38 volumio-principal go-librespot[3244]: time="2024-07-23T10:42:38+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:38 volumio-principal go-librespot[3244]: time="2024-07-23T10:42:38+02: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" Jul 23 10:42:38 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:38 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:38 volumio-principal volumio[3222]: info: Loading plugin "network"... Jul 23 10:42:38 volumio-principal volumio[3222]: info: Refreshing Cached IP Addresses Jul 23 10:42:39 volumio-principal sudo[3253]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 23 10:42:39 volumio-principal sudo[3253]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:39 volumio-principal sudo[3253]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:39 volumio-principal sudo[3255]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "services"... Jul 23 10:42:39 volumio-principal sudo[3255]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "alsa_controller"... Jul 23 10:42:39 volumio-principal sudo[3255]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:39 volumio-principal sudo[3258]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jul 23 10:42:39 volumio-principal sudo[3258]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:39 volumio-principal sudo[3258]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:39 volumio-principal kernel: ieee80211 phy0: brcmf_cfg80211_scan: Connecting: status (3) Jul 23 10:42:39 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "wizard"... Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "volumio_command_line_client"... Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "upnp"... Jul 23 10:42:39 volumio-principal volumio[3222]: info: [1721724159146] Starting Upmpd Daemon Jul 23 10:42:39 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "my_music"... Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "mpd"... Jul 23 10:42:39 volumio-principal squeezeboxserver[3179]: [24-07-23 10:42:37.8843] main::init (377) Starting Logitech Media Server (v8.3.1, 1676361197, Fri 17 Feb 2023 06:39:27 AM CET) perl 5.028001 - arm-linux-gnueabihf-thread-multi-64int Jul 23 10:42:39 volumio-principal squeezeboxserver[3179]: [24-07-23 10:42:38.2650] Slim::Utils::IPDetect::_init (138) Warning: Couldn't call connect() - falling back to 127.0.0.1 Jul 23 10:42:39 volumio-principal volumio[3222]: info: Creating MPD Configuration file Jul 23 10:42:39 volumio-principal sudo[3268]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:42:39 volumio-principal sudo[3268]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "upnp_browser"... Jul 23 10:42:39 volumio-principal sudo[3268]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:39 volumio-principal sudo[3270]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:42:39 volumio-principal sudo[3270]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:39 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:42:39 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:42:39 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:42:39 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:42:39 volumio-principal volumio[3222]: info: Loading plugin "networkfs"... Jul 23 10:42:39 volumio-principal volumio[3222]: info: Starting Udev Watcher for removable devices Jul 23 10:42:40 volumio-principal volumio[3222]: info: Ignoring mount for partition: boot Jul 23 10:42:40 volumio-principal volumio[3222]: info: Ignoring mount for partition: volumio Jul 23 10:42:40 volumio-principal volumio[3222]: info: Ignoring mount for partition: volumio_data Jul 23 10:42:40 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "alarm-clock"... Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "airplay_emulation"... Jul 23 10:42:40 volumio-principal volumio[3222]: info: Starting Shairport Sync Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "last_100"... Jul 23 10:42:40 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "webradio"... Jul 23 10:42:40 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="devolo-961" auth_failures=1 duration=10 reason=CONN_FAILED Jul 23 10:42:40 volumio-principal mpd[3275]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:42:40 volumio-principal mpd[3275]: output: No 'audio_output' defined in config file Jul 23 10:42:40 volumio-principal mpd[3275]: output: Attempt to detect audio output device Jul 23 10:42:40 volumio-principal mpd[3275]: output: Attempting to detect a alsa audio device Jul 23 10:42:40 volumio-principal mpd[3275]: output: Successfully detected a alsa audio device Jul 23 10:42:40 volumio-principal mpd[3275]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:42:40 volumio-principal mpd[3275]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:42:40 volumio-principal mpd[3275]: zeroconf: No global port, disabling zeroconf Jul 23 10:42:40 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:42:40 volumio-principal sudo[3270]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "i2s_dacs"... Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "volumiodiscovery"... Jul 23 10:42:40 volumio-principal volumio[3222]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:40 volumio-principal node[3222]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:40 volumio-principal volumio[3222]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:40 volumio-principal node[3222]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:40 volumio-principal volumio[3222]: *** WARNING *** For more information see Jul 23 10:42:40 volumio-principal node[3222]: *** WARNING *** For more information see Jul 23 10:42:40 volumio-principal volumio[3222]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:40 volumio-principal node[3222]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:40 volumio-principal volumio[3222]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:40 volumio-principal node[3222]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:40 volumio-principal volumio[3222]: *** WARNING *** For more information see Jul 23 10:42:40 volumio-principal node[3222]: *** WARNING *** For more information see Jul 23 10:42:40 volumio-principal volumio[3222]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 23 10:42:40 volumio-principal volumio[3222]: info: Discovery: Started advertising with name: Volumio-Principal Jul 23 10:42:40 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "spop"... Jul 23 10:42:40 volumio-principal volumio[3222]: info: Loading plugin "squeezelite_mc"... Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading plugin "outputs"... Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading plugin "albumart"... Jul 23 10:42:41 volumio-principal volumio[3222]: info: Plugin example_plugin is not enabled Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading plugin "inputs"... Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading plugin "updater_comm"... Jul 23 10:42:41 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:41] [connect] Successful connection Jul 23 10:42:41 volumio-principal volumio[3222]: info: Plugin mpdemulation is not enabled Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading plugin "rest_api"... Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading plugin "websocket"... Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading plugin "lms"... Jul 23 10:42:41 volumio-principal volumio[3222]: Forking 3 albumart workers Jul 23 10:42:41 volumio-principal volumio[3222]: info: Loading i18n strings for locale es Jul 23 10:42:41 volumio-principal volumio[3222]: Updating browse sources language Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::initPlayerControls Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:41 volumio-principal volumio[3222]: Express server listening on port 3000 Jul 23 10:42:41 volumio-principal volumio[3222]: [Metrics] WebUI: 4s 354.97ms Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreStateMachine::resetVolumioState Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreStateMachine::getcurrentVolume Jul 23 10:42:41 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:41 volumio-principal mpd[3275]: client: [0] opened from local Jul 23 10:42:41 volumio-principal volumio[3222]: info: MPD Permissions set Jul 23 10:42:41 volumio-principal volumio[3222]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Jul 23 10:42:41 volumio-principal volumio[3222]: wlan0 Interface doesn't support scanning : Resource temporarily unavailable Jul 23 10:42:41 volumio-principal volumio[3222]: info: Cannot use regular scanning, forcing with ap-force Jul 23 10:42:41 volumio-principal sudo[3316]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Jul 23 10:42:41 volumio-principal sudo[3316]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:42 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:42:42 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jul 23 10:42:42 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:42 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:42 volumio-principal go-librespot[3318]: Librespot-go daemon starting... Jul 23 10:42:42 volumio-principal go-librespot[3318]: time="2024-07-23T10:42:42+02:00" level=info msg="generated new device id: d0e0d4fe00c7ca985510076578046009bab94a4a" Jul 23 10:42:42 volumio-principal go-librespot[3318]: time="2024-07-23T10:42:42+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:42 volumio-principal go-librespot[3318]: time="2024-07-23T10:42:42+02: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" Jul 23 10:42:42 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:42 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:42 volumio-principal volumio[3222]: Starting albumart workers Jul 23 10:42:42 volumio-principal volumio[3222]: Starting albumart workers Jul 23 10:42:42 volumio-principal volumio[3222]: Starting albumart workers Jul 23 10:42:44 volumio-principal sudo[3316]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:44 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:44] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1721724161 101 Jul 23 10:42:44 volumio-principal volumio[3222]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Jul 23 10:42:44 volumio-principal volumio[3222]: info: MPD running with PID3275 Jul 23 10:42:44 volumio-principal volumio[3222]: ,establishing connection Jul 23 10:42:44 volumio-principal mpd[3275]: client: [1] opened from local Jul 23 10:42:44 volumio-principal volumio[3222]: error: MPD error: The expression evaluated to a falsy value: Jul 23 10:42:44 volumio-principal volumio[3222]: assert.ok(self.idling) Jul 23 10:42:44 volumio-principal volumio[3222]: error: The expression evaluated to a falsy value: Jul 23 10:42:44 volumio-principal volumio[3222]: assert.ok(self.idling) Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:44 volumio-principal volumio[3222]: info: Reloading queue from file Jul 23 10:42:44 volumio-principal volumio[3222]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreStateMachine::pushState Jul 23 10:42:44 volumio-principal volumio[3222]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreStateMachine::updateTrackBlock Jul 23 10:42:44 volumio-principal volumio[3222]: info: CorePlayQueue::getTrackBlock Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreStateMachine::setRepeat null single undefined Jul 23 10:42:44 volumio-principal volumio[3222]: info: CoreStateMachine::pushState Jul 23 10:42:45 volumio-principal volumio[3222]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreStateMachine::setRandom null Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreStateMachine::pushState Jul 23 10:42:45 volumio-principal volumio[3222]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:45 volumio-principal volumio[3222]: error: updateQueue error: null Jul 23 10:42:45 volumio-principal volumio[3222]: info: Setting Device type: Raspberry PI Jul 23 10:42:45 volumio-principal volumio[3222]: info: Completed loading Core Plugins Jul 23 10:42:45 volumio-principal volumio[3222]: info: Preparing to generate the ALSA configuration file Jul 23 10:42:45 volumio-principal volumio[3222]: info: Asound.conf file unchanged, so no further update is needed Jul 23 10:42:45 volumio-principal volumio[3222]: info: Output device has changed, restarting MPD Jul 23 10:42:45 volumio-principal sudo[3361]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:42:45 volumio-principal sudo[3361]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:45 volumio-principal volumio[3222]: info: Output device has changed, restarting Shairport Sync Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:45 volumio-principal sudo[3361]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:45 volumio-principal sudo[3364]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:42:45 volumio-principal sudo[3364]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:45 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:42:45 volumio-principal volumio[3222]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:45 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:42:45 volumio-principal volumio[3222]: info: ___________ START PLUGINS ___________ Jul 23 10:42:45 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:42:45 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:45 volumio-principal volumio[3222]: info: [1721724165144] CoreMusicLibrary::Adding element Media Servers Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:45 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:42:45 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jul 23 10:42:45 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:45 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:45 volumio-principal go-librespot[3375]: Librespot-go daemon starting... Jul 23 10:42:45 volumio-principal go-librespot[3375]: time="2024-07-23T10:42:45+02:00" level=info msg="generated new device id: ae89c83bdbd4d03879a12ec11f1e5ec1bf42c937" Jul 23 10:42:45 volumio-principal go-librespot[3375]: time="2024-07-23T10:42:45+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:45 volumio-principal volumio[3222]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:45 volumio-principal volumio[3222]: info: [1721724165245] CoreMusicLibrary::Adding element Last_100 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:45 volumio-principal go-librespot[3375]: time="2024-07-23T10:42:45+02: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" Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:45 volumio-principal volumio[3222]: info: [1721724165248] CoreMusicLibrary::Adding element Webradio Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:45 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:45 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:42:45 volumio-principal volumio[3222]: info: Creating Spotify config file Jul 23 10:42:45 volumio-principal volumio[3222]: info: [squeezelite_mc] Starting proxy server... Jul 23 10:42:45 volumio-principal volumio[3222]: info: Volumio Calling Home Jul 23 10:42:45 volumio-principal sudo[3386]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart logitechmediaserver Jul 23 10:42:45 volumio-principal sudo[3386]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:45 volumio-principal systemd[1]: Stopping Logitech Media Server Daemon... Jul 23 10:42:45 volumio-principal volumio[3222]: info: [squeezelite_mc] Proxy server started on port 46251 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:45 volumio-principal volumio[3222]: Unhandled rejection Error: No sockets available, cannot start. Jul 23 10:42:45 volumio-principal volumio[3222]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Jul 23 10:42:45 volumio-principal volumio[3222]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Jul 23 10:42:45 volumio-principal volumio[3222]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Jul 23 10:42:45 volumio-principal volumio[3222]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Jul 23 10:42:45 volumio-principal volumio[3222]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Jul 23 10:42:45 volumio-principal volumio[3222]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Jul 23 10:42:45 volumio-principal volumio[3222]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Jul 23 10:42:45 volumio-principal volumio[3222]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Jul 23 10:42:45 volumio-principal volumio[3222]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Jul 23 10:42:45 volumio-principal volumio[3222]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Jul 23 10:42:45 volumio-principal volumio[3222]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Jul 23 10:42:45 volumio-principal volumio[3222]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Jul 23 10:42:45 volumio-principal volumio[3222]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Jul 23 10:42:45 volumio-principal volumio[3222]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Jul 23 10:42:45 volumio-principal volumio[3222]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Jul 23 10:42:45 volumio-principal volumio[3222]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jul 23 10:42:45 volumio-principal volumio[3222]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Jul 23 10:42:45 volumio-principal volumio[3222]: info: MPD Permissions set Jul 23 10:42:45 volumio-principal volumio[3222]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreStateMachine::pushState Jul 23 10:42:45 volumio-principal volumio[3222]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:45 volumio-principal volumio[3222]: info: Spotify config file written Jul 23 10:42:45 volumio-principal systemd[1]: logitechmediaserver.service: Succeeded. Jul 23 10:42:45 volumio-principal systemd[1]: Stopped Logitech Media Server Daemon. Jul 23 10:42:45 volumio-principal systemd[1]: Starting Logitech Media Server Daemon... Jul 23 10:42:45 volumio-principal volumio[3222]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal sudo[3395]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal sudo[3395]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal systemd[1]: Started Logitech Media Server Daemon. Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:45 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:45 volumio-principal sudo[3386]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:45 volumio-principal go-librespot[3403]: Librespot-go daemon starting... Jul 23 10:42:45 volumio-principal sudo[3395]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:45 volumio-principal volumio[3222]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreStateMachine::pushState Jul 23 10:42:45 volumio-principal volumio[3222]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:45 volumio-principal volumio[3222]: info: [squeezelite_mc] Server discovery started Jul 23 10:42:45 volumio-principal volumio[3222]: info: [squeezelite_mc] Player finder started Jul 23 10:42:45 volumio-principal go-librespot[3403]: time="2024-07-23T10:42:45+02:00" level=info msg="generated new device id: 57ed7c53f1d2744bc3f5afcbe48a62d4d48268b3" Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:45 volumio-principal volumio[3222]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:45 volumio-principal go-librespot[3403]: time="2024-07-23T10:42:45+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:45 volumio-principal volumio[3222]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Jul 23 10:42:45 volumio-principal go-librespot[3403]: time="2024-07-23T10:42:45+02: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" Jul 23 10:42:45 volumio-principal volumio[3222]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:45 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:45 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:45 volumio-principal volumio[3222]: Error: send ENETUNREACH 255.255.255.255:3483 Jul 23 10:42:45 volumio-principal volumio[3222]: at doSend (dgram.js:692:16) Jul 23 10:42:45 volumio-principal volumio[3222]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Jul 23 10:42:45 volumio-principal volumio[3222]: at afterDns (dgram.js:638:5) Jul 23 10:42:45 volumio-principal volumio[3222]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Jul 23 10:42:45 volumio-principal volumio[3222]: errno: -101, Jul 23 10:42:45 volumio-principal volumio[3222]: code: 'ENETUNREACH', Jul 23 10:42:45 volumio-principal volumio[3222]: syscall: 'send', Jul 23 10:42:45 volumio-principal volumio[3222]: address: '255.255.255.255', Jul 23 10:42:45 volumio-principal volumio[3222]: port: 3483 Jul 23 10:42:45 volumio-principal volumio[3222]: } Jul 23 10:42:45 volumio-principal volumio[3222]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:45 volumio-principal mpd[3384]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:42:45 volumio-principal mpd[3384]: output: No 'audio_output' defined in config file Jul 23 10:42:45 volumio-principal mpd[3384]: output: Attempt to detect audio output device Jul 23 10:42:45 volumio-principal mpd[3384]: output: Attempting to detect a alsa audio device Jul 23 10:42:46 volumio-principal mpd[3384]: output: Successfully detected a alsa audio device Jul 23 10:42:46 volumio-principal mpd[3384]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:42:46 volumio-principal mpd[3384]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:42:46 volumio-principal mpd[3384]: zeroconf: No global port, disabling zeroconf Jul 23 10:42:46 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:42:46 volumio-principal sudo[3364]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:46 volumio-principal sudo[3423]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-23 10:41 Jul 23 10:42:46 volumio-principal sudo[3423]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:46 volumio-principal sudo[3423]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:46 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:46] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jul 23 10:42:46 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:46] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jul 23 10:42:46 volumio-principal systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:46 volumio-principal systemd[1]: volumio.service: Failed with result 'exit-code'. Jul 23 10:42:46 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:46 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:46 volumio-principal systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Jul 23 10:42:46 volumio-principal systemd[1]: volumio.service: Scheduled restart job, restart counter is at 9. Jul 23 10:42:46 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:46 volumio-principal systemd[1]: Stopped Volumio Backend Module. Jul 23 10:42:46 volumio-principal systemd[1]: Started Volumio Backend Module. Jul 23 10:42:46 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:47 volumio-principal volumio[3437]: info: ------------------------------------------- Jul 23 10:42:47 volumio-principal volumio[3437]: info: ----- Volumio3 ---- Jul 23 10:42:47 volumio-principal volumio[3437]: info: ------------------------------------------- Jul 23 10:42:47 volumio-principal volumio[3437]: info: ----- System startup ---- Jul 23 10:42:47 volumio-principal volumio[3437]: info: ------------------------------------------- Jul 23 10:42:48 volumio-principal volumio[3437]: info: MYVOLUMIO Environment detected Jul 23 10:42:48 volumio-principal volumio[3437]: info: Plugin folders cleanup Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning into folder /volumio/app/plugins/ Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning category audio_interface Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning category miscellanea Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning category music_service Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning category plugins.json Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning category system_controller Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning category user_interface Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning into folder /data/plugins/ Jul 23 10:42:48 volumio-principal volumio[3437]: info: Scanning category music_service Jul 23 10:42:48 volumio-principal volumio[3437]: info: Plugin folders cleanup completed Jul 23 10:42:48 volumio-principal volumio[3437]: info: ------------------------------------------- Jul 23 10:42:48 volumio-principal volumio[3437]: info: ----- Core plugins startup ---- Jul 23 10:42:48 volumio-principal volumio[3437]: info: ------------------------------------------- Jul 23 10:42:48 volumio-principal volumio[3437]: info: Loading plugins from folder /volumio/app/plugins/ Jul 23 10:42:48 volumio-principal volumio[3437]: info: Adding plugin upnp to MyMusic Plugins Jul 23 10:42:48 volumio-principal volumio[3437]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 23 10:42:48 volumio-principal volumio[3437]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 23 10:42:48 volumio-principal volumio[3437]: info: Loading plugins from folder /data/plugins/ Jul 23 10:42:48 volumio-principal volumio[3437]: info: Loading plugin "system"... Jul 23 10:42:48 volumio-principal volumio[3437]: info: Loading plugin "appearance"... Jul 23 10:42:48 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:42:48 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jul 23 10:42:48 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:48 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:48 volumio-principal go-librespot[3459]: Librespot-go daemon starting... Jul 23 10:42:48 volumio-principal go-librespot[3459]: time="2024-07-23T10:42:48+02:00" level=info msg="generated new device id: c1d6ba25b2bbf9fb5302c6d53d9ce3f5cd214284" Jul 23 10:42:48 volumio-principal go-librespot[3459]: time="2024-07-23T10:42:48+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:48 volumio-principal go-librespot[3459]: time="2024-07-23T10:42:48+02: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" Jul 23 10:42:48 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:48 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:48 volumio-principal volumio[3437]: info: Loading plugin "network"... Jul 23 10:42:48 volumio-principal volumio[3437]: info: Refreshing Cached IP Addresses Jul 23 10:42:49 volumio-principal sudo[3467]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 23 10:42:49 volumio-principal sudo[3467]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:49 volumio-principal sudo[3467]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:49 volumio-principal sudo[3469]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "services"... Jul 23 10:42:49 volumio-principal sudo[3469]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "alsa_controller"... Jul 23 10:42:49 volumio-principal sudo[3469]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:49 volumio-principal sudo[3473]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jul 23 10:42:49 volumio-principal sudo[3473]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:49 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "wizard"... Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "volumio_command_line_client"... Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "upnp"... Jul 23 10:42:49 volumio-principal volumio[3437]: info: [1721724169142] Starting Upmpd Daemon Jul 23 10:42:49 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "my_music"... Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "mpd"... Jul 23 10:42:49 volumio-principal squeezeboxserver[3402]: [24-07-23 10:42:47.8346] main::init (377) Starting Logitech Media Server (v8.3.1, 1676361197, Fri 17 Feb 2023 06:39:27 AM CET) perl 5.028001 - arm-linux-gnueabihf-thread-multi-64int Jul 23 10:42:49 volumio-principal squeezeboxserver[3402]: [24-07-23 10:42:48.2191] Slim::Utils::IPDetect::_init (138) Warning: Couldn't call connect() - falling back to 127.0.0.1 Jul 23 10:42:49 volumio-principal volumio[3437]: info: Creating MPD Configuration file Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "upnp_browser"... Jul 23 10:42:49 volumio-principal sudo[3482]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:42:49 volumio-principal sudo[3482]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:49 volumio-principal sudo[3482]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:49 volumio-principal sudo[3484]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:42:49 volumio-principal sudo[3484]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:49 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:42:49 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:42:49 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:42:49 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:42:49 volumio-principal volumio[3437]: info: Loading plugin "networkfs"... Jul 23 10:42:49 volumio-principal volumio[3437]: info: Starting Udev Watcher for removable devices Jul 23 10:42:49 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="devolo-961" Jul 23 10:42:49 volumio-principal wpa_supplicant[758]: wlan0: Failed to initiate sched scan Jul 23 10:42:50 volumio-principal volumio[3437]: info: Ignoring mount for partition: boot Jul 23 10:42:50 volumio-principal volumio[3437]: info: Ignoring mount for partition: volumio Jul 23 10:42:50 volumio-principal volumio[3437]: info: Ignoring mount for partition: volumio_data Jul 23 10:42:50 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "alarm-clock"... Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "airplay_emulation"... Jul 23 10:42:50 volumio-principal volumio[3437]: info: Starting Shairport Sync Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "last_100"... Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "webradio"... Jul 23 10:42:50 volumio-principal mpd[3489]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:42:50 volumio-principal mpd[3489]: output: No 'audio_output' defined in config file Jul 23 10:42:50 volumio-principal mpd[3489]: output: Attempt to detect audio output device Jul 23 10:42:50 volumio-principal mpd[3489]: output: Attempting to detect a alsa audio device Jul 23 10:42:50 volumio-principal mpd[3489]: output: Successfully detected a alsa audio device Jul 23 10:42:50 volumio-principal mpd[3489]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:42:50 volumio-principal mpd[3489]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:42:50 volumio-principal mpd[3489]: zeroconf: No global port, disabling zeroconf Jul 23 10:42:50 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:42:50 volumio-principal sudo[3484]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "i2s_dacs"... Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "volumiodiscovery"... Jul 23 10:42:50 volumio-principal volumio[3437]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:50 volumio-principal volumio[3437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:50 volumio-principal node[3437]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:50 volumio-principal volumio[3437]: *** WARNING *** For more information see Jul 23 10:42:50 volumio-principal volumio[3437]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:50 volumio-principal volumio[3437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:50 volumio-principal volumio[3437]: *** WARNING *** For more information see Jul 23 10:42:50 volumio-principal node[3437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:50 volumio-principal node[3437]: *** WARNING *** For more information see Jul 23 10:42:50 volumio-principal node[3437]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:50 volumio-principal node[3437]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:50 volumio-principal node[3437]: *** WARNING *** For more information see Jul 23 10:42:50 volumio-principal volumio[3437]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 23 10:42:50 volumio-principal volumio[3437]: info: Discovery: Started advertising with name: Volumio-Principal Jul 23 10:42:50 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "spop"... Jul 23 10:42:50 volumio-principal volumio[3437]: info: Loading plugin "squeezelite_mc"... Jul 23 10:42:51 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:51] [connect] Successful connection Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading plugin "outputs"... Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading plugin "albumart"... Jul 23 10:42:51 volumio-principal volumio[3437]: info: Plugin example_plugin is not enabled Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading plugin "inputs"... Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading plugin "updater_comm"... Jul 23 10:42:51 volumio-principal volumio[3437]: info: Plugin mpdemulation is not enabled Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading plugin "rest_api"... Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading plugin "websocket"... Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading plugin "lms"... Jul 23 10:42:51 volumio-principal volumio[3437]: Forking 3 albumart workers Jul 23 10:42:51 volumio-principal volumio[3437]: info: Loading i18n strings for locale es Jul 23 10:42:51 volumio-principal volumio[3437]: Updating browse sources language Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::initPlayerControls Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:51 volumio-principal volumio[3437]: Express server listening on port 3000 Jul 23 10:42:51 volumio-principal volumio[3437]: [Metrics] WebUI: 4s 376.92ms Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreStateMachine::resetVolumioState Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreStateMachine::getcurrentVolume Jul 23 10:42:51 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:51 volumio-principal mpd[3489]: client: [0] opened from local Jul 23 10:42:51 volumio-principal volumio[3437]: info: MPD Permissions set Jul 23 10:42:51 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:51] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1721724171 101 Jul 23 10:42:51 volumio-principal volumio[3437]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Jul 23 10:42:51 volumio-principal volumio[3437]: info: MPD running with PID3489 Jul 23 10:42:51 volumio-principal volumio[3437]: ,establishing connection Jul 23 10:42:51 volumio-principal mpd[3489]: client: [1] opened from local Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:42:52 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jul 23 10:42:52 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:52 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:52 volumio-principal go-librespot[3538]: Librespot-go daemon starting... Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: Reloading queue from file Jul 23 10:42:52 volumio-principal volumio[3437]: error: updateQueue error: null Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreStateMachine::setRepeat null single undefined Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreStateMachine::pushState Jul 23 10:42:52 volumio-principal volumio[3437]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:52 volumio-principal go-librespot[3538]: time="2024-07-23T10:42:52+02:00" level=info msg="generated new device id: a254bafd0bd89cf97f1f42e1206f9732830a526e" Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 23 10:42:52 volumio-principal go-librespot[3538]: time="2024-07-23T10:42:52+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:52 volumio-principal go-librespot[3538]: time="2024-07-23T10:42:52+02: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" Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreStateMachine::setRandom null Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreStateMachine::pushState Jul 23 10:42:52 volumio-principal volumio[3437]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:52 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:52 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:52 volumio-principal volumio[3437]: info: Setting Device type: Raspberry PI Jul 23 10:42:52 volumio-principal volumio[3437]: info: Completed loading Core Plugins Jul 23 10:42:52 volumio-principal volumio[3437]: info: Preparing to generate the ALSA configuration file Jul 23 10:42:52 volumio-principal volumio[3437]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreStateMachine::pushState Jul 23 10:42:52 volumio-principal volumio[3437]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreStateMachine::updateTrackBlock Jul 23 10:42:52 volumio-principal volumio[3437]: info: CorePlayQueue::getTrackBlock Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:52 volumio-principal volumio[3437]: Starting albumart workers Jul 23 10:42:52 volumio-principal volumio[3437]: Starting albumart workers Jul 23 10:42:52 volumio-principal volumio[3437]: error: updateQueue error: null Jul 23 10:42:52 volumio-principal volumio[3437]: info: Asound.conf file unchanged, so no further update is needed Jul 23 10:42:52 volumio-principal volumio[3437]: info: Output device has changed, restarting MPD Jul 23 10:42:52 volumio-principal volumio[3437]: Starting albumart workers Jul 23 10:42:52 volumio-principal volumio[3437]: info: Output device has changed, restarting Shairport Sync Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:52 volumio-principal sudo[3546]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:42:52 volumio-principal sudo[3546]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:52 volumio-principal sudo[3546]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:52 volumio-principal sudo[3549]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:42:52 volumio-principal sudo[3549]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:52 volumio-principal volumio[3437]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:52 volumio-principal volumio[3437]: info: ___________ START PLUGINS ___________ Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:52 volumio-principal volumio[3437]: info: [1721724172331] CoreMusicLibrary::Adding element Media Servers Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:52 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:52 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:42:52 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:42:52 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:42:52 volumio-principal volumio[3437]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:52 volumio-principal volumio[3437]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:52 volumio-principal volumio[3437]: info: [1721724172490] CoreMusicLibrary::Adding element Last_100 Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:42:52 volumio-principal volumio[3437]: info: [1721724172495] CoreMusicLibrary::Adding element Webradio Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:42:52 volumio-principal volumio[3437]: info: Creating Spotify config file Jul 23 10:42:52 volumio-principal volumio[3437]: info: [squeezelite_mc] Starting proxy server... Jul 23 10:42:52 volumio-principal volumio[3437]: info: Volumio Calling Home Jul 23 10:42:52 volumio-principal sudo[3580]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart logitechmediaserver Jul 23 10:42:52 volumio-principal sudo[3580]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:52 volumio-principal systemd[1]: Stopping Logitech Media Server Daemon... Jul 23 10:42:52 volumio-principal volumio[3437]: info: [squeezelite_mc] Proxy server started on port 41687 Jul 23 10:42:52 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:52 volumio-principal volumio[3437]: Unhandled rejection Error: No sockets available, cannot start. Jul 23 10:42:52 volumio-principal volumio[3437]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Jul 23 10:42:52 volumio-principal volumio[3437]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Jul 23 10:42:52 volumio-principal volumio[3437]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Jul 23 10:42:52 volumio-principal volumio[3437]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Jul 23 10:42:52 volumio-principal volumio[3437]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Jul 23 10:42:52 volumio-principal volumio[3437]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Jul 23 10:42:52 volumio-principal volumio[3437]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Jul 23 10:42:52 volumio-principal volumio[3437]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Jul 23 10:42:52 volumio-principal volumio[3437]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Jul 23 10:42:52 volumio-principal volumio[3437]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Jul 23 10:42:52 volumio-principal volumio[3437]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Jul 23 10:42:52 volumio-principal volumio[3437]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Jul 23 10:42:52 volumio-principal volumio[3437]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Jul 23 10:42:52 volumio-principal volumio[3437]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Jul 23 10:42:52 volumio-principal volumio[3437]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Jul 23 10:42:52 volumio-principal volumio[3437]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jul 23 10:42:52 volumio-principal volumio[3437]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Jul 23 10:42:52 volumio-principal systemd[1]: logitechmediaserver.service: Succeeded. Jul 23 10:42:52 volumio-principal systemd[1]: Stopped Logitech Media Server Daemon. Jul 23 10:42:52 volumio-principal volumio[3437]: info: MPD Permissions set Jul 23 10:42:52 volumio-principal systemd[1]: Starting Logitech Media Server Daemon... Jul 23 10:42:52 volumio-principal systemd[1]: Started Logitech Media Server Daemon. Jul 23 10:42:52 volumio-principal sudo[3580]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:52 volumio-principal volumio[3437]: info: Spotify config file written Jul 23 10:42:53 volumio-principal sudo[3600]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 23 10:42:53 volumio-principal sudo[3600]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:53 volumio-principal volumio[3437]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:53 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:53 volumio-principal go-librespot[3603]: Librespot-go daemon starting... Jul 23 10:42:53 volumio-principal sudo[3600]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal go-librespot[3603]: time="2024-07-23T10:42:53+02:00" level=info msg="generated new device id: ad99edf848212593e554d89821adcbaca8206814" Jul 23 10:42:53 volumio-principal go-librespot[3603]: time="2024-07-23T10:42:53+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:53 volumio-principal go-librespot[3603]: time="2024-07-23T10:42:53+02: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" Jul 23 10:42:53 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:53 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:53 volumio-principal volumio[3437]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreStateMachine::pushState Jul 23 10:42:53 volumio-principal volumio[3437]: info: CorePlayQueue::getTrack 0 Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::volumioPushState Jul 23 10:42:53 volumio-principal volumio[3437]: info: [squeezelite_mc] Server discovery started Jul 23 10:42:53 volumio-principal volumio[3437]: info: [squeezelite_mc] Player finder started Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:53 volumio-principal volumio[3437]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Jul 23 10:42:53 volumio-principal volumio[3437]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:53 volumio-principal volumio[3437]: Error: send ENETUNREACH 255.255.255.255:3483 Jul 23 10:42:53 volumio-principal volumio[3437]: at doSend (dgram.js:692:16) Jul 23 10:42:53 volumio-principal volumio[3437]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Jul 23 10:42:53 volumio-principal volumio[3437]: at afterDns (dgram.js:638:5) Jul 23 10:42:53 volumio-principal volumio[3437]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Jul 23 10:42:53 volumio-principal volumio[3437]: errno: -101, Jul 23 10:42:53 volumio-principal volumio[3437]: code: 'ENETUNREACH', Jul 23 10:42:53 volumio-principal volumio[3437]: syscall: 'send', Jul 23 10:42:53 volumio-principal volumio[3437]: address: '255.255.255.255', Jul 23 10:42:53 volumio-principal volumio[3437]: port: 3483 Jul 23 10:42:53 volumio-principal volumio[3437]: } Jul 23 10:42:53 volumio-principal volumio[3437]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:42:53 volumio-principal mpd[3562]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:42:53 volumio-principal mpd[3562]: output: No 'audio_output' defined in config file Jul 23 10:42:53 volumio-principal mpd[3562]: output: Attempt to detect audio output device Jul 23 10:42:53 volumio-principal mpd[3562]: output: Attempting to detect a alsa audio device Jul 23 10:42:53 volumio-principal mpd[3562]: output: Successfully detected a alsa audio device Jul 23 10:42:53 volumio-principal mpd[3562]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:42:53 volumio-principal mpd[3562]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:42:53 volumio-principal mpd[3562]: zeroconf: No global port, disabling zeroconf Jul 23 10:42:53 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:42:53 volumio-principal sudo[3549]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:53 volumio-principal sudo[3627]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-23 10:41 Jul 23 10:42:53 volumio-principal sudo[3627]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:53 volumio-principal sudo[3627]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:53 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:53] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jul 23 10:42:53 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:53] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jul 23 10:42:53 volumio-principal systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:53 volumio-principal sudo[3473]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:53 volumio-principal systemd[1]: volumio.service: Failed with result 'exit-code'. Jul 23 10:42:53 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:53 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:54 volumio-principal systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Jul 23 10:42:54 volumio-principal systemd[1]: volumio.service: Scheduled restart job, restart counter is at 10. Jul 23 10:42:54 volumio-principal systemd[1]: Stopped Volumio Backend Module. Jul 23 10:42:54 volumio-principal systemd[1]: Started Volumio Backend Module. Jul 23 10:42:54 volumio-principal systemd[1]: Started dynamicswap service. Jul 23 10:42:54 volumio-principal systemd[1]: dynamicswap.service: Succeeded. Jul 23 10:42:54 volumio-principal wpa_supplicant[758]: wlan0: Trying to associate with SSID 'devolo-961' Jul 23 10:42:55 volumio-principal volumio[3640]: info: ------------------------------------------- Jul 23 10:42:55 volumio-principal volumio[3640]: info: ----- Volumio3 ---- Jul 23 10:42:55 volumio-principal volumio[3640]: info: ------------------------------------------- Jul 23 10:42:55 volumio-principal volumio[3640]: info: ----- System startup ---- Jul 23 10:42:55 volumio-principal volumio[3640]: info: ------------------------------------------- Jul 23 10:42:55 volumio-principal volumio[3640]: info: MYVOLUMIO Environment detected Jul 23 10:42:55 volumio-principal volumio[3640]: info: Plugin folders cleanup Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning into folder /volumio/app/plugins/ Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning category audio_interface Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning category miscellanea Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning category music_service Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning category plugins.json Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning category system_controller Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning category user_interface Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning into folder /data/plugins/ Jul 23 10:42:55 volumio-principal volumio[3640]: info: Scanning category music_service Jul 23 10:42:55 volumio-principal volumio[3640]: info: Plugin folders cleanup completed Jul 23 10:42:55 volumio-principal volumio[3640]: info: ------------------------------------------- Jul 23 10:42:55 volumio-principal volumio[3640]: info: ----- Core plugins startup ---- Jul 23 10:42:55 volumio-principal volumio[3640]: info: ------------------------------------------- Jul 23 10:42:55 volumio-principal volumio[3640]: info: Loading plugins from folder /volumio/app/plugins/ Jul 23 10:42:55 volumio-principal volumio[3640]: info: Adding plugin upnp to MyMusic Plugins Jul 23 10:42:55 volumio-principal volumio[3640]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 23 10:42:55 volumio-principal volumio[3640]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 23 10:42:55 volumio-principal volumio[3640]: info: Loading plugins from folder /data/plugins/ Jul 23 10:42:55 volumio-principal volumio[3640]: info: Loading plugin "system"... Jul 23 10:42:55 volumio-principal volumio[3640]: info: Loading plugin "appearance"... Jul 23 10:42:56 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:42:56 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jul 23 10:42:56 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:56 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:56 volumio-principal go-librespot[3663]: Librespot-go daemon starting... Jul 23 10:42:56 volumio-principal go-librespot[3663]: time="2024-07-23T10:42:56+02:00" level=info msg="generated new device id: a7d80877499e5e0ecdabbb45e10d02242f23125e" Jul 23 10:42:56 volumio-principal go-librespot[3663]: time="2024-07-23T10:42:56+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:56 volumio-principal go-librespot[3663]: time="2024-07-23T10:42:56+02: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" Jul 23 10:42:56 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:56 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "network"... Jul 23 10:42:56 volumio-principal volumio[3640]: info: Refreshing Cached IP Addresses Jul 23 10:42:56 volumio-principal sudo[3672]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 23 10:42:56 volumio-principal sudo[3672]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:56 volumio-principal sudo[3672]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:56 volumio-principal sudo[3674]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "services"... Jul 23 10:42:56 volumio-principal sudo[3674]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "alsa_controller"... Jul 23 10:42:56 volumio-principal sudo[3674]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:56 volumio-principal sudo[3678]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jul 23 10:42:56 volumio-principal sudo[3678]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:56 volumio-principal sudo[3678]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:56 volumio-principal kernel: ieee80211 phy0: brcmf_cfg80211_scan: Connecting: status (3) Jul 23 10:42:56 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "wizard"... Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "volumio_command_line_client"... Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "upnp"... Jul 23 10:42:56 volumio-principal volumio[3640]: info: [1721724176612] Starting Upmpd Daemon Jul 23 10:42:56 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "my_music"... Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "mpd"... Jul 23 10:42:56 volumio-principal squeezeboxserver[3597]: [24-07-23 10:42:55.1840] main::init (377) Starting Logitech Media Server (v8.3.1, 1676361197, Fri 17 Feb 2023 06:39:27 AM CET) perl 5.028001 - arm-linux-gnueabihf-thread-multi-64int Jul 23 10:42:56 volumio-principal squeezeboxserver[3597]: [24-07-23 10:42:55.5659] Slim::Utils::IPDetect::_init (138) Warning: Couldn't call connect() - falling back to 127.0.0.1 Jul 23 10:42:56 volumio-principal volumio[3640]: info: Creating MPD Configuration file Jul 23 10:42:56 volumio-principal volumio[3640]: info: Loading plugin "upnp_browser"... Jul 23 10:42:56 volumio-principal sudo[3687]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:42:56 volumio-principal sudo[3687]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:56 volumio-principal sudo[3687]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:56 volumio-principal sudo[3689]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:42:56 volumio-principal sudo[3689]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:56 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:42:56 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:42:56 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:42:56 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "networkfs"... Jul 23 10:42:57 volumio-principal volumio[3640]: info: Starting Udev Watcher for removable devices Jul 23 10:42:57 volumio-principal volumio[3640]: info: Ignoring mount for partition: boot Jul 23 10:42:57 volumio-principal volumio[3640]: info: Ignoring mount for partition: volumio Jul 23 10:42:57 volumio-principal volumio[3640]: info: Ignoring mount for partition: volumio_data Jul 23 10:42:57 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "alarm-clock"... Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "airplay_emulation"... Jul 23 10:42:57 volumio-principal volumio[3640]: info: Starting Shairport Sync Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "last_100"... Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "webradio"... Jul 23 10:42:57 volumio-principal dhcpcd[770]: wlan0: carrier acquired Jul 23 10:42:57 volumio-principal wpa_supplicant[758]: wlan0: Associated with b8:be:f4:bc:78:d5 Jul 23 10:42:57 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-CONNECTED - Connection to b8:be:f4:bc:78:d5 completed [id=0 id_str=] Jul 23 10:42:57 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Jul 23 10:42:57 volumio-principal dhcpcd[770]: wlan0: IAID dd:80:f5:90 Jul 23 10:42:57 volumio-principal dhcpcd[770]: wlan0: carrier lost Jul 23 10:42:57 volumio-principal mpd[3694]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:42:57 volumio-principal mpd[3694]: output: No 'audio_output' defined in config file Jul 23 10:42:57 volumio-principal mpd[3694]: output: Attempt to detect audio output device Jul 23 10:42:57 volumio-principal mpd[3694]: output: Attempting to detect a alsa audio device Jul 23 10:42:57 volumio-principal mpd[3694]: output: Successfully detected a alsa audio device Jul 23 10:42:57 volumio-principal mpd[3694]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:42:57 volumio-principal mpd[3694]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:42:57 volumio-principal dhcpcd[770]: wlan0: carrier acquired Jul 23 10:42:57 volumio-principal wpa_supplicant[758]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Jul 23 10:42:57 volumio-principal mpd[3694]: zeroconf: No global port, disabling zeroconf Jul 23 10:42:57 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:42:57 volumio-principal dhcpcd[770]: wlan0: IAID dd:80:f5:90 Jul 23 10:42:57 volumio-principal sudo[3689]: pam_unix(sudo:session): session closed for user root Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "i2s_dacs"... Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "volumiodiscovery"... Jul 23 10:42:57 volumio-principal volumio[3640]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:57 volumio-principal volumio[3640]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:57 volumio-principal volumio[3640]: *** WARNING *** For more information see Jul 23 10:42:57 volumio-principal node[3640]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:57 volumio-principal volumio[3640]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:57 volumio-principal volumio[3640]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:57 volumio-principal volumio[3640]: *** WARNING *** For more information see Jul 23 10:42:57 volumio-principal node[3640]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:57 volumio-principal node[3640]: *** WARNING *** For more information see Jul 23 10:42:57 volumio-principal node[3640]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 23 10:42:57 volumio-principal node[3640]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 23 10:42:57 volumio-principal node[3640]: *** WARNING *** For more information see Jul 23 10:42:57 volumio-principal volumio[3640]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 23 10:42:57 volumio-principal volumio[3640]: info: Discovery: Started advertising with name: Volumio-Principal Jul 23 10:42:57 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 23 10:42:57 volumio-principal volumio[3640]: info: Loading plugin "spop"... Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "squeezelite_mc"... Jul 23 10:42:58 volumio-principal dhcpcd[770]: wlan0: rebinding lease of 192.168.100.125 Jul 23 10:42:58 volumio-principal dhcpcd[770]: wlan0: probing address 192.168.100.125/24 Jul 23 10:42:58 volumio-principal dhcpcd[770]: wlan0: soliciting an IPv6 router Jul 23 10:42:58 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:42:58] [connect] Successful connection Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "outputs"... Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "albumart"... Jul 23 10:42:58 volumio-principal volumio[3640]: info: Plugin example_plugin is not enabled Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "inputs"... Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "updater_comm"... Jul 23 10:42:58 volumio-principal volumio[3640]: info: Plugin mpdemulation is not enabled Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "rest_api"... Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "websocket"... Jul 23 10:42:58 volumio-principal volumio[3640]: info: Loading plugin "lms"... Jul 23 10:42:59 volumio-principal volumio[3640]: info: Loading i18n strings for locale es Jul 23 10:42:59 volumio-principal volumio[3640]: Forking 3 albumart workers Jul 23 10:42:59 volumio-principal volumio[3640]: Updating browse sources language Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::initPlayerControls Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:42:59 volumio-principal volumio[3640]: Express server listening on port 3000 Jul 23 10:42:59 volumio-principal volumio[3640]: [Metrics] WebUI: 4s 338.74ms Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreStateMachine::resetVolumioState Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreStateMachine::getcurrentVolume Jul 23 10:42:59 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:42:59 volumio-principal mpd[3694]: client: [0] opened from local Jul 23 10:42:59 volumio-principal volumio[3640]: info: MPD Permissions set Jul 23 10:42:59 volumio-principal volumio[3640]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Jul 23 10:42:59 volumio-principal volumio[3640]: wlan0 Interface doesn't support scanning : Resource temporarily unavailable Jul 23 10:42:59 volumio-principal volumio[3640]: info: Cannot use regular scanning, forcing with ap-force Jul 23 10:42:59 volumio-principal sudo[3750]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Jul 23 10:42:59 volumio-principal sudo[3750]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:42:59 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:42:59 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jul 23 10:42:59 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:42:59 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:42:59 volumio-principal go-librespot[3752]: Librespot-go daemon starting... Jul 23 10:42:59 volumio-principal volumio[3640]: Starting albumart workers Jul 23 10:42:59 volumio-principal go-librespot[3752]: time="2024-07-23T10:42:59+02:00" level=info msg="generated new device id: 3065669589d7cef230ec1cc036370ad70e71623f" Jul 23 10:42:59 volumio-principal go-librespot[3752]: time="2024-07-23T10:42:59+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:42:59 volumio-principal volumio[3640]: Starting albumart workers Jul 23 10:42:59 volumio-principal volumio[3640]: Starting albumart workers Jul 23 10:42:59 volumio-principal go-librespot[3752]: time="2024-07-23T10:42:59+02: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" Jul 23 10:42:59 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:42:59 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:43:02 volumio-principal systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 23 10:43:02 volumio-principal systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jul 23 10:43:02 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:43:02 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:43:02 volumio-principal go-librespot[3784]: Librespot-go daemon starting... Jul 23 10:43:02 volumio-principal go-librespot[3784]: time="2024-07-23T10:43:02+02:00" level=info msg="generated new device id: 099357fd5095ead7a92fff5be6ac7173a47fb46a" Jul 23 10:43:02 volumio-principal go-librespot[3784]: time="2024-07-23T10:43:02+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:43:02 volumio-principal go-librespot[3784]: time="2024-07-23T10:43:02+02: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" Jul 23 10:43:02 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:43:02 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:43:03 volumio-principal sudo[3750]: pam_unix(sudo:session): session closed for user root Jul 23 10:43:03 volumio-principal volumio-remote-updater[490]: [2024-07-23 10:43:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1721724178 101 Jul 23 10:43:03 volumio-principal volumio[3640]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Jul 23 10:43:03 volumio-principal volumio[3640]: info: MPD running with PID3694 Jul 23 10:43:03 volumio-principal volumio[3640]: ,establishing connection Jul 23 10:43:03 volumio-principal mpd[3694]: client: [1] opened from local Jul 23 10:43:03 volumio-principal volumio[3640]: error: MPD error: The expression evaluated to a falsy value: Jul 23 10:43:03 volumio-principal volumio[3640]: assert.ok(self.idling) Jul 23 10:43:03 volumio-principal volumio[3640]: error: The expression evaluated to a falsy value: Jul 23 10:43:03 volumio-principal volumio[3640]: assert.ok(self.idling) Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: Reloading queue from file Jul 23 10:43:03 volumio-principal volumio[3640]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::pushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: CorePlayQueue::getTrack 0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioPushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::updateTrackBlock Jul 23 10:43:03 volumio-principal volumio[3640]: info: CorePlayQueue::getTrackBlock Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::setRepeat null single undefined Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::pushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: CorePlayQueue::getTrack 0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioPushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::setRandom null Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::pushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: CorePlayQueue::getTrack 0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioPushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: Setting Device type: Raspberry PI Jul 23 10:43:03 volumio-principal volumio[3640]: error: updateQueue error: null Jul 23 10:43:03 volumio-principal volumio[3640]: info: Completed loading Core Plugins Jul 23 10:43:03 volumio-principal volumio[3640]: info: Preparing to generate the ALSA configuration file Jul 23 10:43:03 volumio-principal volumio[3640]: info: Asound.conf file unchanged, so no further update is needed Jul 23 10:43:03 volumio-principal volumio[3640]: info: Output device has changed, restarting MPD Jul 23 10:43:03 volumio-principal sudo[3803]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 23 10:43:03 volumio-principal sudo[3803]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:43:03 volumio-principal volumio[3640]: info: Output device has changed, restarting Shairport Sync Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:43:03 volumio-principal sudo[3803]: pam_unix(sudo:session): session closed for user root Jul 23 10:43:03 volumio-principal sudo[3805]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 23 10:43:03 volumio-principal sudo[3805]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:43:03 volumio-principal systemd[1]: Stopping Music Player Daemon... Jul 23 10:43:03 volumio-principal volumio[3640]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: ___________ START PLUGINS ___________ Jul 23 10:43:03 volumio-principal systemd[1]: mpd.service: Succeeded. Jul 23 10:43:03 volumio-principal systemd[1]: Stopped Music Player Daemon. Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:43:03 volumio-principal volumio[3640]: info: [1721724183395] CoreMusicLibrary::Adding element Media Servers Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:43:03 volumio-principal systemd[1]: Starting Music Player Daemon... Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:43:03 volumio-principal volumio[3640]: info: [1721724183492] CoreMusicLibrary::Adding element Last_100 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 23 10:43:03 volumio-principal volumio[3640]: info: [1721724183495] CoreMusicLibrary::Adding element Webradio Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 23 10:43:03 volumio-principal volumio[3640]: info: Creating Spotify config file Jul 23 10:43:03 volumio-principal volumio[3640]: info: [squeezelite_mc] Starting proxy server... Jul 23 10:43:03 volumio-principal volumio[3640]: info: Volumio Calling Home Jul 23 10:43:03 volumio-principal sudo[3821]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart logitechmediaserver Jul 23 10:43:03 volumio-principal sudo[3821]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:43:03 volumio-principal systemd[1]: Stopping Logitech Media Server Daemon... Jul 23 10:43:03 volumio-principal volumio[3640]: info: [squeezelite_mc] Proxy server started on port 39781 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioRetrievevolume Jul 23 10:43:03 volumio-principal volumio[3640]: Unhandled rejection Error: No sockets available, cannot start. Jul 23 10:43:03 volumio-principal volumio[3640]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Jul 23 10:43:03 volumio-principal volumio[3640]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Jul 23 10:43:03 volumio-principal volumio[3640]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Jul 23 10:43:03 volumio-principal volumio[3640]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Jul 23 10:43:03 volumio-principal volumio[3640]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Jul 23 10:43:03 volumio-principal volumio[3640]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Jul 23 10:43:03 volumio-principal volumio[3640]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Jul 23 10:43:03 volumio-principal volumio[3640]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Jul 23 10:43:03 volumio-principal volumio[3640]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Jul 23 10:43:03 volumio-principal volumio[3640]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Jul 23 10:43:03 volumio-principal volumio[3640]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Jul 23 10:43:03 volumio-principal volumio[3640]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Jul 23 10:43:03 volumio-principal volumio[3640]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Jul 23 10:43:03 volumio-principal volumio[3640]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Jul 23 10:43:03 volumio-principal volumio[3640]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Jul 23 10:43:03 volumio-principal volumio[3640]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jul 23 10:43:03 volumio-principal systemd[1]: logitechmediaserver.service: Succeeded. Jul 23 10:43:03 volumio-principal systemd[1]: Stopped Logitech Media Server Daemon. Jul 23 10:43:03 volumio-principal volumio[3640]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.dfs.volumio.org Jul 23 10:43:03 volumio-principal systemd[1]: Starting Logitech Media Server Daemon... Jul 23 10:43:03 volumio-principal volumio[3640]: info: MPD Permissions set Jul 23 10:43:03 volumio-principal volumio[3640]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::pushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: CorePlayQueue::getTrack 0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioPushState Jul 23 10:43:03 volumio-principal systemd[1]: Started Logitech Media Server Daemon. Jul 23 10:43:03 volumio-principal sudo[3821]: pam_unix(sudo:session): session closed for user root Jul 23 10:43:03 volumio-principal volumio[3640]: info: Spotify config file written Jul 23 10:43:03 volumio-principal volumio[3640]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Jul 23 10:43:03 volumio-principal volumio[3640]: info: logitechmediaserver started Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal sudo[3832]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 23 10:43:03 volumio-principal sudo[3832]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal systemd[1]: Stopped go-librespot Daemon. Jul 23 10:43:03 volumio-principal systemd[1]: Started go-librespot Daemon. Jul 23 10:43:03 volumio-principal go-librespot[3838]: Librespot-go daemon starting... Jul 23 10:43:03 volumio-principal sudo[3832]: pam_unix(sudo:session): session closed for user root Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal go-librespot[3838]: time="2024-07-23T10:43:03+02:00" level=info msg="generated new device id: fb49c245c55a82961c6f9e0b9a9296cf38073cfb" Jul 23 10:43:03 volumio-principal go-librespot[3838]: time="2024-07-23T10:43:03+02:00" level=debug msg="stored credentials found for gcerruela" Jul 23 10:43:03 volumio-principal go-librespot[3838]: time="2024-07-23T10:43:03+02: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" Jul 23 10:43:03 volumio-principal systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 23 10:43:03 volumio-principal systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 23 10:43:03 volumio-principal volumio[3640]: info: VolumeController:: Volume=43 Mute =false Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreStateMachine::pushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: CorePlayQueue::getTrack 0 Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::volumioPushState Jul 23 10:43:03 volumio-principal volumio[3640]: info: [squeezelite_mc] Server discovery started Jul 23 10:43:03 volumio-principal volumio[3640]: info: [squeezelite_mc] Player finder started Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 23 10:43:03 volumio-principal volumio[3640]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Jul 23 10:43:04 volumio-principal volumio[3640]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:43:04 volumio-principal volumio[3640]: Error: send ENETUNREACH 255.255.255.255:3483 Jul 23 10:43:04 volumio-principal volumio[3640]: at doSend (dgram.js:692:16) Jul 23 10:43:04 volumio-principal volumio[3640]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Jul 23 10:43:04 volumio-principal volumio[3640]: at afterDns (dgram.js:638:5) Jul 23 10:43:04 volumio-principal volumio[3640]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Jul 23 10:43:04 volumio-principal volumio[3640]: errno: -101, Jul 23 10:43:04 volumio-principal volumio[3640]: code: 'ENETUNREACH', Jul 23 10:43:04 volumio-principal volumio[3640]: syscall: 'send', Jul 23 10:43:04 volumio-principal volumio[3640]: address: '255.255.255.255', Jul 23 10:43:04 volumio-principal volumio[3640]: port: 3483 Jul 23 10:43:04 volumio-principal volumio[3640]: } Jul 23 10:43:04 volumio-principal volumio[3640]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 23 10:43:04 volumio-principal mpd[3819]: exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 23 10:43:04 volumio-principal mpd[3819]: output: No 'audio_output' defined in config file Jul 23 10:43:04 volumio-principal mpd[3819]: output: Attempt to detect audio output device Jul 23 10:43:04 volumio-principal mpd[3819]: output: Attempting to detect a alsa audio device Jul 23 10:43:04 volumio-principal mpd[3819]: output: Successfully detected a alsa audio device Jul 23 10:43:04 volumio-principal mpd[3819]: exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Jul 23 10:43:04 volumio-principal mpd[3819]: exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Jul 23 10:43:04 volumio-principal mpd[3819]: zeroconf: No global port, disabling zeroconf Jul 23 10:43:04 volumio-principal systemd[1]: Started Music Player Daemon. Jul 23 10:43:04 volumio-principal sudo[3805]: pam_unix(sudo:session): session closed for user root Jul 23 10:43:04 volumio-principal dhcpcd[770]: wlan0: leased 192.168.100.125 for 86400 seconds Jul 23 10:43:04 volumio-principal avahi-daemon[516]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.100.125. Jul 23 10:43:04 volumio-principal avahi-daemon[516]: New relevant interface wlan0.IPv4 for mDNS. Jul 23 10:43:04 volumio-principal dhcpcd[770]: wlan0: adding route to 192.168.100.0/24 Jul 23 10:43:04 volumio-principal avahi-daemon[516]: Registering new address record for 192.168.100.125 on wlan0.IPv4. Jul 23 10:43:04 volumio-principal dhcpcd[770]: wlan0: adding default route via 192.168.100.1 Jul 23 10:43:04 volumio-principal sudo[3880]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-23 10:42 Jul 23 10:43:04 volumio-principal sudo[3880]: 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="cd8cf34b47ce852e70b71e6f7b6e0265f7fdb695" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="8f88153f9a18f312d56050e6613b45a852ac819a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 27 Sep 2023 11:35:49 AM CEST" VOLUMIO_VERSION="3.546" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="6823c0d83061ff736b7e0dd4481bc496"