-- Logs begin at Tue 2024-10-29 23:01:37 CST, end at Wed 2024-10-30 01:06:38 CST. -- Oct 30 01:05:00 volumiopi3 mpd[6578]: Oct 30 01:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:05:00 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:00 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:05:00 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:00 volumiopi3 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 30 01:05:00 volumiopi3 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2. Oct 30 01:05:00 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:00 volumiopi3 systemd[1]: Stopped Volumio Backend Module. Oct 30 01:05:00 volumiopi3 systemd[1]: Started Volumio Backend Module. Oct 30 01:05:00 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:01 volumiopi3 volumio[6674]: info: ------------------------------------------- Oct 30 01:05:01 volumiopi3 volumio[6674]: info: ----- Volumio3 ---- Oct 30 01:05:01 volumiopi3 volumio[6674]: info: ------------------------------------------- Oct 30 01:05:01 volumiopi3 volumio[6674]: info: ----- System startup ---- Oct 30 01:05:01 volumiopi3 volumio[6674]: info: ------------------------------------------- Oct 30 01:05:02 volumiopi3 volumio[6674]: info: MYVOLUMIO Environment detected Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Plugin folders cleanup Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning into folder /volumio/app/plugins/ Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning category audio_interface Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning category miscellanea Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning category music_service Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning category plugins.json Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning category system_controller Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning category user_interface Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning into folder /data/plugins/ Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Scanning category music_service Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Plugin folders cleanup completed Oct 30 01:05:02 volumiopi3 volumio[6674]: info: ------------------------------------------- Oct 30 01:05:02 volumiopi3 volumio[6674]: info: ----- Core plugins startup ---- Oct 30 01:05:02 volumiopi3 volumio[6674]: info: ------------------------------------------- Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Adding plugin upnp to MyMusic Plugins Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Loading plugins from folder /data/plugins/ Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Loading plugin "system"... Oct 30 01:05:02 volumiopi3 volumio[6674]: info: Loading plugin "appearance"... Oct 30 01:05:03 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:05:03] [connect] Successful connection Oct 30 01:05:03 volumiopi3 wpa_supplicant[887]: wlan0: Failed to initiate sched scan Oct 30 01:05:03 volumiopi3 volumio[6674]: info: Loading plugin "network"... Oct 30 01:05:03 volumiopi3 volumio[6674]: info: Refreshing Cached IP Addresses Oct 30 01:05:03 volumiopi3 sudo[6701]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 01:05:03 volumiopi3 sudo[6701]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:03 volumiopi3 sudo[6701]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:03 volumiopi3 sudo[6703]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 01:05:03 volumiopi3 sudo[6703]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:03 volumiopi3 volumio[6674]: info: Loading plugin "services"... Oct 30 01:05:03 volumiopi3 volumio[6674]: info: Loading plugin "alsa_controller"... Oct 30 01:05:03 volumiopi3 sudo[6703]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:03 volumiopi3 sudo[6706]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 30 01:05:03 volumiopi3 sudo[6706]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:03 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:03 volumiopi3 volumio[6674]: info: Loading plugin "wizard"... Oct 30 01:05:03 volumiopi3 volumio[6674]: info: Loading plugin "networkfs"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Starting Udev Watcher for removable devices Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Ignoring mount for partition: boot Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Ignoring mount for partition: volumio Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Ignoring mount for partition: volumio_data Oct 30 01:05:04 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "volumio_command_line_client"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "upnp"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: [1730221504067] Starting Upmpd Daemon Oct 30 01:05:04 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "my_music"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "mpd"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "upnp_browser"... Oct 30 01:05:04 volumiopi3 sudo[6706]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "alarm-clock"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "airplay_emulation"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Starting Shairport Sync Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "last_100"... Oct 30 01:05:04 volumiopi3 volumio[6674]: info: Loading plugin "webradio"... Oct 30 01:05:05 volumiopi3 volumio[6674]: info: Loading plugin "i2s_dacs"... Oct 30 01:05:05 volumiopi3 volumio[6674]: info: Loading plugin "volumiodiscovery"... Oct 30 01:05:05 volumiopi3 volumio[6674]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:05 volumiopi3 node[6674]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:05 volumiopi3 volumio[6674]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:05 volumiopi3 node[6674]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:05 volumiopi3 volumio[6674]: *** WARNING *** For more information see Oct 30 01:05:05 volumiopi3 node[6674]: *** WARNING *** For more information see Oct 30 01:05:05 volumiopi3 volumio[6674]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:05 volumiopi3 node[6674]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:05 volumiopi3 volumio[6674]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:05 volumiopi3 node[6674]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:05 volumiopi3 volumio[6674]: *** WARNING *** For more information see Oct 30 01:05:05 volumiopi3 node[6674]: *** WARNING *** For more information see Oct 30 01:05:05 volumiopi3 volumio[6674]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 01:05:05 volumiopi3 volumio[6674]: info: Discovery: Started advertising with name: VolumioPI3 Oct 30 01:05:05 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:05 volumiopi3 volumio[6674]: info: Loading plugin "spop"... Oct 30 01:05:06 volumiopi3 volumio[6674]: info: Loading plugin "squeezelite_mc"... Oct 30 01:05:06 volumiopi3 volumio[6674]: info: Loading plugin "ytcr"... Oct 30 01:05:09 volumiopi3 volumio[6674]: info: Loading plugin "ytmusic"... Oct 30 01:05:09 volumiopi3 wpa_supplicant[887]: wlan0: Trying to associate with SSID 'philiveroom' Oct 30 01:05:09 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Loading plugin "outputs"... Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Loading plugin "albumart"... Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Plugin example_plugin is not enabled Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Loading plugin "inputs"... Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Loading plugin "updater_comm"... Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Plugin mpdemulation is not enabled Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Loading plugin "rest_api"... Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Loading plugin "websocket"... Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Starting Socket.io Server version 2.3.0 Oct 30 01:05:10 volumiopi3 volumio[6674]: info: Loading i18n strings for locale en Oct 30 01:05:10 volumiopi3 volumio[6674]: Updating browse sources language Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:10 volumiopi3 wpa_supplicant[887]: wlan0: Trying to associate with SSID 'philiveroom' Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::initPlayerControls Oct 30 01:05:10 volumiopi3 volumio[6674]: Forking 3 albumart workers Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:10 volumiopi3 volumio[6674]: Express server listening on port 3000 Oct 30 01:05:10 volumiopi3 volumio[6674]: [Metrics] WebUI: 9s 571.41ms Oct 30 01:05:10 volumiopi3 volumio[6674]: info: CoreStateMachine::resetVolumioState Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreStateMachine::getcurrentVolume Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreStateMachine::pushState Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Reloading queue from file Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreStateMachine::setRepeat null single undefined Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreStateMachine::pushState Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreStateMachine::setRandom null Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreStateMachine::pushState Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Setting Device type: Raspberry PI Oct 30 01:05:11 volumiopi3 volumio[6674]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 01:05:11 volumiopi3 volumio[6674]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Completed loading Core Plugins Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Preparing to generate the ALSA configuration file Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Asound.conf file unchanged, so no further update is needed Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Output device has changed, restarting MPD Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Output device has changed, restarting Shairport Sync Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:11 volumiopi3 sudo[6750]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:11 volumiopi3 sudo[6750]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:11 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Oct 30 01:05:11 volumiopi3 sudo[6750]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:11 volumiopi3 sudo[6751]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:11 volumiopi3 sudo[6751]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: ___________ START PLUGINS ___________ Oct 30 01:05:11 volumiopi3 volumio[6674]: info: ControllerMpd::onStart: Initializing MPD Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Creating MPD Configuration file Oct 30 01:05:11 volumiopi3 systemd[1]: Stopping Music Player Daemon... Oct 30 01:05:11 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:11 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:11 volumiopi3 volumio[6674]: info: [1730221511559] CoreMusicLibrary::Adding element Media Servers Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:11 volumiopi3 sudo[6759]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:11 volumiopi3 sudo[6759]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:11 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:11 volumiopi3 sudo[6761]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:11 volumiopi3 sudo[6761]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:11 volumiopi3 sudo[6759]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:11 volumiopi3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 30 01:05:11 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:11 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:11 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:11 volumiopi3 volumio[6674]: info: [1730221511750] CoreMusicLibrary::Adding element Last_100 Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:11 volumiopi3 volumio[6674]: info: [1730221511754] CoreMusicLibrary::Adding element Webradio Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Initializing BBC Radios Oct 30 01:05:11 volumiopi3 sudo[6771]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:05:11 volumiopi3 sudo[6771]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:11 volumiopi3 sudo[6771]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:11 volumiopi3 volumio[6674]: info: Creating Spotify config file Oct 30 01:05:11 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:12 volumiopi3 volumio[6674]: Starting albumart workers Oct 30 01:05:12 volumiopi3 volumio[6674]: Starting albumart workers Oct 30 01:05:12 volumiopi3 volumio[6674]: info: [squeezelite_mc] Starting proxy server... Oct 30 01:05:12 volumiopi3 volumio[6674]: Starting albumart workers Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:12 volumiopi3 volumio[6674]: info: [1730221512433] CoreMusicLibrary::Adding element YouTube Music Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:12 volumiopi3 volumio[6674]: Cannot find translation for source YouTube Music Oct 30 01:05:12 volumiopi3 volumio[6674]: info: Volumio Calling Home Oct 30 01:05:12 volumiopi3 volumio[6674]: info: [squeezelite_mc] Proxy server started on port 43213 Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioGetState Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreStateMachine::pushState Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:12 volumiopi3 volumio[6674]: info: [squeezelite_mc] Server discovery started Oct 30 01:05:12 volumiopi3 volumio[6674]: info: [squeezelite_mc] Player finder started Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:12 volumiopi3 volumio[6674]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:12 volumiopi3 volumio[6674]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 30 01:05:12 volumiopi3 wpa_supplicant[887]: wlan0: Trying to associate with SSID 'philiveroom' Oct 30 01:05:12 volumiopi3 volumio[6674]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:12 volumiopi3 volumio[6674]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 30 01:05:12 volumiopi3 volumio[6674]: at doSend (dgram.js:692:16) Oct 30 01:05:12 volumiopi3 volumio[6674]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 30 01:05:12 volumiopi3 volumio[6674]: at afterDns (dgram.js:638:5) Oct 30 01:05:12 volumiopi3 volumio[6674]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 30 01:05:12 volumiopi3 volumio[6674]: errno: -101, Oct 30 01:05:12 volumiopi3 volumio[6674]: code: 'ENETUNREACH', Oct 30 01:05:12 volumiopi3 volumio[6674]: syscall: 'send', Oct 30 01:05:12 volumiopi3 volumio[6674]: address: '255.255.255.255', Oct 30 01:05:12 volumiopi3 volumio[6674]: port: 3483 Oct 30 01:05:12 volumiopi3 volumio[6674]: } Oct 30 01:05:12 volumiopi3 volumio[6674]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:13 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Oct 30 01:05:13 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="philiveroom" auth_failures=1 duration=10 reason=CONN_FAILED Oct 30 01:05:13 volumiopi3 sudo[6822]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 01:04 Oct 30 01:05:13 volumiopi3 sudo[6822]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:13 volumiopi3 sudo[6822]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:13 volumiopi3 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:05:13 volumiopi3 mpd[6783]: Oct 30 01:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:05:13 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:05:13 volumiopi3 sudo[6751]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:13 volumiopi3 sudo[6761]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:13 volumiopi3 systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 01:05:14 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:14 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:14 volumiopi3 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 30 01:05:14 volumiopi3 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3. Oct 30 01:05:14 volumiopi3 systemd[1]: Stopped Volumio Backend Module. Oct 30 01:05:14 volumiopi3 systemd[1]: Started Volumio Backend Module. Oct 30 01:05:14 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:14 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:15 volumiopi3 volumio[6838]: info: ------------------------------------------- Oct 30 01:05:15 volumiopi3 volumio[6838]: info: ----- Volumio3 ---- Oct 30 01:05:15 volumiopi3 volumio[6838]: info: ------------------------------------------- Oct 30 01:05:15 volumiopi3 volumio[6838]: info: ----- System startup ---- Oct 30 01:05:15 volumiopi3 volumio[6838]: info: ------------------------------------------- Oct 30 01:05:16 volumiopi3 volumio[6838]: info: MYVOLUMIO Environment detected Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Plugin folders cleanup Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning into folder /volumio/app/plugins/ Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning category audio_interface Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning category miscellanea Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning category music_service Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning category plugins.json Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning category system_controller Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning category user_interface Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning into folder /data/plugins/ Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Scanning category music_service Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Plugin folders cleanup completed Oct 30 01:05:16 volumiopi3 volumio[6838]: info: ------------------------------------------- Oct 30 01:05:16 volumiopi3 volumio[6838]: info: ----- Core plugins startup ---- Oct 30 01:05:16 volumiopi3 volumio[6838]: info: ------------------------------------------- Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Adding plugin upnp to MyMusic Plugins Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Loading plugins from folder /data/plugins/ Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Loading plugin "system"... Oct 30 01:05:16 volumiopi3 volumio[6838]: info: Loading plugin "appearance"... Oct 30 01:05:17 volumiopi3 volumio[6838]: info: Loading plugin "network"... Oct 30 01:05:17 volumiopi3 volumio[6838]: info: Refreshing Cached IP Addresses Oct 30 01:05:17 volumiopi3 sudo[6866]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 01:05:17 volumiopi3 sudo[6866]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:17 volumiopi3 sudo[6866]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:17 volumiopi3 volumio[6838]: info: Loading plugin "services"... Oct 30 01:05:17 volumiopi3 sudo[6868]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 01:05:17 volumiopi3 sudo[6868]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:17 volumiopi3 volumio[6838]: info: Loading plugin "alsa_controller"... Oct 30 01:05:17 volumiopi3 sudo[6868]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:17 volumiopi3 sudo[6871]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 30 01:05:17 volumiopi3 sudo[6871]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:17 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:17 volumiopi3 volumio[6838]: info: Loading plugin "wizard"... Oct 30 01:05:17 volumiopi3 volumio[6838]: info: Loading plugin "networkfs"... Oct 30 01:05:17 volumiopi3 volumio[6838]: info: Starting Udev Watcher for removable devices Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Ignoring mount for partition: boot Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Ignoring mount for partition: volumio Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Ignoring mount for partition: volumio_data Oct 30 01:05:18 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "volumio_command_line_client"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "upnp"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: [1730221518036] Starting Upmpd Daemon Oct 30 01:05:18 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "my_music"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "mpd"... Oct 30 01:05:18 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:05:18] [connect] Successful connection Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "upnp_browser"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "alarm-clock"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "airplay_emulation"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Starting Shairport Sync Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "last_100"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "webradio"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "i2s_dacs"... Oct 30 01:05:18 volumiopi3 volumio[6838]: info: Loading plugin "volumiodiscovery"... Oct 30 01:05:19 volumiopi3 sudo[6871]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:19 volumiopi3 volumio[6838]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:19 volumiopi3 volumio[6838]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:19 volumiopi3 volumio[6838]: *** WARNING *** For more information see Oct 30 01:05:19 volumiopi3 volumio[6838]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:19 volumiopi3 node[6838]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:19 volumiopi3 volumio[6838]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:19 volumiopi3 volumio[6838]: *** WARNING *** For more information see Oct 30 01:05:19 volumiopi3 node[6838]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:19 volumiopi3 node[6838]: *** WARNING *** For more information see Oct 30 01:05:19 volumiopi3 node[6838]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:19 volumiopi3 node[6838]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:19 volumiopi3 node[6838]: *** WARNING *** For more information see Oct 30 01:05:19 volumiopi3 volumio[6838]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 01:05:19 volumiopi3 volumio[6838]: info: Discovery: Started advertising with name: VolumioPI3 Oct 30 01:05:19 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:19 volumiopi3 volumio[6838]: info: Loading plugin "spop"... Oct 30 01:05:20 volumiopi3 volumio[6838]: info: Loading plugin "squeezelite_mc"... Oct 30 01:05:20 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:20+08:00" level=error msg="did not receive last pong from dealer, 60s passed" Oct 30 01:05:20 volumiopi3 volumio[6838]: info: Loading plugin "ytcr"... Oct 30 01:05:22 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="philiveroom" Oct 30 01:05:22 volumiopi3 wpa_supplicant[887]: wlan0: Trying to associate with SSID 'philiveroom' Oct 30 01:05:23 volumiopi3 volumio[6838]: info: Loading plugin "ytmusic"... Oct 30 01:05:23 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Oct 30 01:05:23 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="philiveroom" auth_failures=2 duration=23 reason=CONN_FAILED Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Loading plugin "outputs"... Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Loading plugin "albumart"... Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Plugin example_plugin is not enabled Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Loading plugin "inputs"... Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Loading plugin "updater_comm"... Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Plugin mpdemulation is not enabled Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Loading plugin "rest_api"... Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Loading plugin "websocket"... Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Starting Socket.io Server version 2.3.0 Oct 30 01:05:24 volumiopi3 volumio[6838]: info: Loading i18n strings for locale en Oct 30 01:05:24 volumiopi3 volumio[6838]: Updating browse sources language Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::initPlayerControls Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: Forking 3 albumart workers Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:24 volumiopi3 volumio[6838]: Express server listening on port 3000 Oct 30 01:05:24 volumiopi3 volumio[6838]: [Metrics] WebUI: 9s 504.21ms Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreStateMachine::resetVolumioState Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreStateMachine::getcurrentVolume Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreStateMachine::pushState Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:24 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Reloading queue from file Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreStateMachine::setRepeat null single undefined Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreStateMachine::pushState Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreStateMachine::setRandom null Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreStateMachine::pushState Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Setting Device type: Raspberry PI Oct 30 01:05:25 volumiopi3 volumio[6838]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 01:05:25 volumiopi3 volumio[6838]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 30 01:05:25 volumiopi3 volumio[6838]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Completed loading Core Plugins Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Preparing to generate the ALSA configuration file Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Asound.conf file unchanged, so no further update is needed Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Output device has changed, restarting MPD Oct 30 01:05:25 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:25+08:00" level=error msg="failed receiving dealer message" error="failed to get reader: WebSocket closed: sent close frame: status = StatusServiceRestart and reason = \"\"" Oct 30 01:05:25 volumiopi3 sudo[6914]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:25 volumiopi3 sudo[6914]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Output device has changed, restarting Shairport Sync Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:25 volumiopi3 sudo[6914]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:25 volumiopi3 sudo[6917]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:25 volumiopi3 sudo[6917]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:25 volumiopi3 volumio[6838]: info: ___________ START PLUGINS ___________ Oct 30 01:05:25 volumiopi3 volumio[6838]: info: ControllerMpd::onStart: Initializing MPD Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Creating MPD Configuration file Oct 30 01:05:25 volumiopi3 systemd[1]: Stopping Music Player Daemon... Oct 30 01:05:25 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:25 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:25 volumiopi3 volumio[6838]: info: [1730221525550] CoreMusicLibrary::Adding element Media Servers Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:25 volumiopi3 sudo[6923]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:25 volumiopi3 sudo[6923]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:25 volumiopi3 sudo[6925]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:25 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:25 volumiopi3 sudo[6925]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:25 volumiopi3 sudo[6923]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:25 volumiopi3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 30 01:05:25 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:25 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:25 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:25 volumiopi3 sudo[6935]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:05:25 volumiopi3 sudo[6935]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:25 volumiopi3 sudo[6935]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:25 volumiopi3 volumio[6838]: info: [1730221525885] CoreMusicLibrary::Adding element Last_100 Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:25 volumiopi3 volumio[6838]: info: [1730221525891] CoreMusicLibrary::Adding element Webradio Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:25 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:25 volumiopi3 volumio[6838]: info: Initializing BBC Radios Oct 30 01:05:26 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:26+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:26 volumiopi3 volumio[6838]: Starting albumart workers Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:26 volumiopi3 volumio[6838]: info: Creating Spotify config file Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:26 volumiopi3 volumio[6838]: Starting albumart workers Oct 30 01:05:26 volumiopi3 volumio[6838]: Starting albumart workers Oct 30 01:05:26 volumiopi3 volumio[6838]: info: [squeezelite_mc] Starting proxy server... Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:26 volumiopi3 volumio[6838]: info: [1730221526458] CoreMusicLibrary::Adding element YouTube Music Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:26 volumiopi3 volumio[6838]: Cannot find translation for source YouTube Music Oct 30 01:05:26 volumiopi3 volumio[6838]: info: Volumio Calling Home Oct 30 01:05:26 volumiopi3 volumio[6838]: info: [squeezelite_mc] Proxy server started on port 40919 Oct 30 01:05:26 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:26+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioGetState Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreStateMachine::pushState Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:26 volumiopi3 volumio[6838]: info: [squeezelite_mc] Server discovery started Oct 30 01:05:26 volumiopi3 volumio[6838]: info: [squeezelite_mc] Player finder started Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:26 volumiopi3 volumio[6838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:26 volumiopi3 volumio[6838]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 30 01:05:26 volumiopi3 volumio[6838]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:26 volumiopi3 volumio[6838]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 30 01:05:26 volumiopi3 volumio[6838]: at doSend (dgram.js:692:16) Oct 30 01:05:26 volumiopi3 volumio[6838]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 30 01:05:26 volumiopi3 volumio[6838]: at afterDns (dgram.js:638:5) Oct 30 01:05:26 volumiopi3 volumio[6838]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 30 01:05:26 volumiopi3 volumio[6838]: errno: -101, Oct 30 01:05:26 volumiopi3 volumio[6838]: code: 'ENETUNREACH', Oct 30 01:05:26 volumiopi3 volumio[6838]: syscall: 'send', Oct 30 01:05:26 volumiopi3 volumio[6838]: address: '255.255.255.255', Oct 30 01:05:26 volumiopi3 volumio[6838]: port: 3483 Oct 30 01:05:26 volumiopi3 volumio[6838]: } Oct 30 01:05:26 volumiopi3 volumio[6838]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:27 volumiopi3 sudo[6989]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 01:04 Oct 30 01:05:27 volumiopi3 sudo[6989]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:27 volumiopi3 sudo[6989]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:27 volumiopi3 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:05:27 volumiopi3 sudo[6917]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:27 volumiopi3 sudo[6925]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:27 volumiopi3 systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 01:05:27 volumiopi3 mpd[6940]: Oct 30 01:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:05:27 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:05:27 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:27 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:28 volumiopi3 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 30 01:05:28 volumiopi3 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4. Oct 30 01:05:28 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:28 volumiopi3 systemd[1]: Stopped Volumio Backend Module. Oct 30 01:05:28 volumiopi3 systemd[1]: Started Volumio Backend Module. Oct 30 01:05:28 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:28 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:28+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:29 volumiopi3 volumio[7006]: info: ------------------------------------------- Oct 30 01:05:29 volumiopi3 volumio[7006]: info: ----- Volumio3 ---- Oct 30 01:05:29 volumiopi3 volumio[7006]: info: ------------------------------------------- Oct 30 01:05:29 volumiopi3 volumio[7006]: info: ----- System startup ---- Oct 30 01:05:29 volumiopi3 volumio[7006]: info: ------------------------------------------- Oct 30 01:05:30 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:30+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:30 volumiopi3 volumio[7006]: info: MYVOLUMIO Environment detected Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Plugin folders cleanup Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning into folder /volumio/app/plugins/ Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning category audio_interface Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning category miscellanea Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning category music_service Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning category plugins.json Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning category system_controller Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning category user_interface Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning into folder /data/plugins/ Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Scanning category music_service Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Plugin folders cleanup completed Oct 30 01:05:30 volumiopi3 volumio[7006]: info: ------------------------------------------- Oct 30 01:05:30 volumiopi3 volumio[7006]: info: ----- Core plugins startup ---- Oct 30 01:05:30 volumiopi3 volumio[7006]: info: ------------------------------------------- Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Adding plugin upnp to MyMusic Plugins Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Loading plugins from folder /data/plugins/ Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Loading plugin "system"... Oct 30 01:05:30 volumiopi3 volumio[7006]: info: Loading plugin "appearance"... Oct 30 01:05:31 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:31+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Loading plugin "network"... Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Refreshing Cached IP Addresses Oct 30 01:05:31 volumiopi3 sudo[7032]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 01:05:31 volumiopi3 sudo[7032]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:31 volumiopi3 sudo[7032]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Loading plugin "services"... Oct 30 01:05:31 volumiopi3 sudo[7034]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 01:05:31 volumiopi3 sudo[7034]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Loading plugin "alsa_controller"... Oct 30 01:05:31 volumiopi3 sudo[7034]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:31 volumiopi3 sudo[7037]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 30 01:05:31 volumiopi3 sudo[7037]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:31 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Loading plugin "wizard"... Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Loading plugin "networkfs"... Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Starting Udev Watcher for removable devices Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Ignoring mount for partition: boot Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Ignoring mount for partition: volumio Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Ignoring mount for partition: volumio_data Oct 30 01:05:31 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:31 volumiopi3 volumio[7006]: info: Loading plugin "volumio_command_line_client"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "upnp"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: [1730221532010] Starting Upmpd Daemon Oct 30 01:05:32 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "my_music"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "mpd"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "upnp_browser"... Oct 30 01:05:32 volumiopi3 sudo[7037]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "alarm-clock"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "airplay_emulation"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Starting Shairport Sync Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "last_100"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "webradio"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "i2s_dacs"... Oct 30 01:05:32 volumiopi3 volumio[7006]: info: Loading plugin "volumiodiscovery"... Oct 30 01:05:33 volumiopi3 volumio[7006]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:33 volumiopi3 volumio[7006]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:33 volumiopi3 volumio[7006]: *** WARNING *** For more information see Oct 30 01:05:33 volumiopi3 volumio[7006]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:33 volumiopi3 node[7006]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:33 volumiopi3 volumio[7006]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:33 volumiopi3 volumio[7006]: *** WARNING *** For more information see Oct 30 01:05:33 volumiopi3 node[7006]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:33 volumiopi3 node[7006]: *** WARNING *** For more information see Oct 30 01:05:33 volumiopi3 node[7006]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:33 volumiopi3 node[7006]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:33 volumiopi3 node[7006]: *** WARNING *** For more information see Oct 30 01:05:33 volumiopi3 volumio[7006]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 01:05:33 volumiopi3 volumio[7006]: info: Discovery: Started advertising with name: VolumioPI3 Oct 30 01:05:33 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:33 volumiopi3 volumio[7006]: info: Loading plugin "spop"... Oct 30 01:05:33 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:05:33] [connect] Successful connection Oct 30 01:05:34 volumiopi3 volumio[7006]: info: Loading plugin "squeezelite_mc"... Oct 30 01:05:34 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:34+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:34 volumiopi3 volumio[7006]: info: Loading plugin "ytcr"... Oct 30 01:05:37 volumiopi3 volumio[7006]: info: Loading plugin "ytmusic"... Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Loading plugin "outputs"... Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Loading plugin "albumart"... Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Plugin example_plugin is not enabled Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Loading plugin "inputs"... Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Loading plugin "updater_comm"... Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Plugin mpdemulation is not enabled Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Loading plugin "rest_api"... Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Loading plugin "websocket"... Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Starting Socket.io Server version 2.3.0 Oct 30 01:05:38 volumiopi3 volumio[7006]: info: Loading i18n strings for locale en Oct 30 01:05:38 volumiopi3 volumio[7006]: Updating browse sources language Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::initPlayerControls Oct 30 01:05:38 volumiopi3 volumio[7006]: Forking 3 albumart workers Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:38 volumiopi3 volumio[7006]: Express server listening on port 3000 Oct 30 01:05:38 volumiopi3 volumio[7006]: [Metrics] WebUI: 9s 463.32ms Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreStateMachine::resetVolumioState Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreStateMachine::getcurrentVolume Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreStateMachine::pushState Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:38 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Reloading queue from file Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Setting Device type: Raspberry PI Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreStateMachine::setRepeat null single undefined Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreStateMachine::pushState Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreStateMachine::setRandom null Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreStateMachine::pushState Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:39 volumiopi3 volumio[7006]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 01:05:39 volumiopi3 volumio[7006]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 30 01:05:39 volumiopi3 volumio[7006]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Completed loading Core Plugins Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Preparing to generate the ALSA configuration file Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Asound.conf file unchanged, so no further update is needed Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Output device has changed, restarting MPD Oct 30 01:05:39 volumiopi3 sudo[7081]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:39 volumiopi3 sudo[7081]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Output device has changed, restarting Shairport Sync Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:39 volumiopi3 sudo[7081]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:39 volumiopi3 sudo[7084]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:39 volumiopi3 sudo[7084]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:39 volumiopi3 systemd[1]: Stopping Music Player Daemon... Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:39 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:39 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:39 volumiopi3 volumio[7006]: info: ___________ START PLUGINS ___________ Oct 30 01:05:39 volumiopi3 volumio[7006]: info: ControllerMpd::onStart: Initializing MPD Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Creating MPD Configuration file Oct 30 01:05:39 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:39 volumiopi3 sudo[7091]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:39 volumiopi3 sudo[7091]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:39 volumiopi3 volumio[7006]: info: [1730221539603] CoreMusicLibrary::Adding element Media Servers Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:39 volumiopi3 sudo[7093]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:39 volumiopi3 sudo[7091]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:39 volumiopi3 sudo[7093]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:39 volumiopi3 sudo[7089]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:05:39 volumiopi3 sudo[7089]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:39 volumiopi3 sudo[7089]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:39 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:39 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:39 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:39 volumiopi3 volumio[7006]: info: [1730221539866] CoreMusicLibrary::Adding element Last_100 Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:39 volumiopi3 volumio[7006]: info: [1730221539871] CoreMusicLibrary::Adding element Webradio Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:39 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:39 volumiopi3 volumio[7006]: info: Initializing BBC Radios Oct 30 01:05:39 volumiopi3 sudo[7097]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:05:39 volumiopi3 sudo[7097]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:39 volumiopi3 sudo[7097]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:40 volumiopi3 volumio[7006]: Starting albumart workers Oct 30 01:05:40 volumiopi3 volumio[7006]: Starting albumart workers Oct 30 01:05:40 volumiopi3 volumio[7006]: Starting albumart workers Oct 30 01:05:40 volumiopi3 volumio[7006]: info: Creating Spotify config file Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:40 volumiopi3 volumio[7006]: info: [squeezelite_mc] Starting proxy server... Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:40 volumiopi3 volumio[7006]: info: [1730221540328] CoreMusicLibrary::Adding element YouTube Music Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:40 volumiopi3 volumio[7006]: Cannot find translation for source YouTube Music Oct 30 01:05:40 volumiopi3 volumio[7006]: info: Volumio Calling Home Oct 30 01:05:40 volumiopi3 volumio[7006]: info: [squeezelite_mc] Proxy server started on port 46221 Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioGetState Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreStateMachine::pushState Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:40 volumiopi3 volumio[7006]: info: [squeezelite_mc] Server discovery started Oct 30 01:05:40 volumiopi3 volumio[7006]: info: [squeezelite_mc] Player finder started Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:40 volumiopi3 volumio[7006]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:40 volumiopi3 volumio[7006]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 30 01:05:40 volumiopi3 volumio[7006]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:40 volumiopi3 volumio[7006]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 30 01:05:40 volumiopi3 volumio[7006]: at doSend (dgram.js:692:16) Oct 30 01:05:40 volumiopi3 volumio[7006]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 30 01:05:40 volumiopi3 volumio[7006]: at afterDns (dgram.js:638:5) Oct 30 01:05:40 volumiopi3 volumio[7006]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 30 01:05:40 volumiopi3 volumio[7006]: errno: -101, Oct 30 01:05:40 volumiopi3 volumio[7006]: code: 'ENETUNREACH', Oct 30 01:05:40 volumiopi3 volumio[7006]: syscall: 'send', Oct 30 01:05:40 volumiopi3 volumio[7006]: address: '255.255.255.255', Oct 30 01:05:40 volumiopi3 volumio[7006]: port: 3483 Oct 30 01:05:40 volumiopi3 volumio[7006]: } Oct 30 01:05:40 volumiopi3 volumio[7006]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:41 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:41+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:41 volumiopi3 sudo[7154]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 01:04 Oct 30 01:05:41 volumiopi3 sudo[7154]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:41 volumiopi3 sudo[7154]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:41 volumiopi3 mpd[7111]: Oct 30 01:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:05:41 volumiopi3 sudo[7093]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:41 volumiopi3 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:05:41 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:05:41 volumiopi3 sudo[7084]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:41 volumiopi3 systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 01:05:42 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:42 volumiopi3 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 30 01:05:42 volumiopi3 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 5. Oct 30 01:05:42 volumiopi3 systemd[1]: Stopped Volumio Backend Module. Oct 30 01:05:42 volumiopi3 systemd[1]: Started Volumio Backend Module. Oct 30 01:05:42 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:43 volumiopi3 volumio[7169]: info: ------------------------------------------- Oct 30 01:05:43 volumiopi3 volumio[7169]: info: ----- Volumio3 ---- Oct 30 01:05:43 volumiopi3 volumio[7169]: info: ------------------------------------------- Oct 30 01:05:43 volumiopi3 volumio[7169]: info: ----- System startup ---- Oct 30 01:05:43 volumiopi3 volumio[7169]: info: ------------------------------------------- Oct 30 01:05:44 volumiopi3 volumio[7169]: info: MYVOLUMIO Environment detected Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Plugin folders cleanup Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning into folder /volumio/app/plugins/ Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning category audio_interface Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning category miscellanea Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning category music_service Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning category plugins.json Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning category system_controller Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning category user_interface Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning into folder /data/plugins/ Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Scanning category music_service Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Plugin folders cleanup completed Oct 30 01:05:44 volumiopi3 volumio[7169]: info: ------------------------------------------- Oct 30 01:05:44 volumiopi3 volumio[7169]: info: ----- Core plugins startup ---- Oct 30 01:05:44 volumiopi3 volumio[7169]: info: ------------------------------------------- Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Adding plugin upnp to MyMusic Plugins Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Loading plugins from folder /data/plugins/ Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Loading plugin "system"... Oct 30 01:05:44 volumiopi3 volumio[7169]: info: Loading plugin "appearance"... Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Loading plugin "network"... Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Refreshing Cached IP Addresses Oct 30 01:05:45 volumiopi3 sudo[7190]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 01:05:45 volumiopi3 sudo[7190]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:45 volumiopi3 sudo[7190]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:45 volumiopi3 sudo[7192]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Loading plugin "services"... Oct 30 01:05:45 volumiopi3 sudo[7192]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Loading plugin "alsa_controller"... Oct 30 01:05:45 volumiopi3 sudo[7192]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:45 volumiopi3 sudo[7195]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 30 01:05:45 volumiopi3 sudo[7195]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:45 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Loading plugin "wizard"... Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Loading plugin "networkfs"... Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Starting Udev Watcher for removable devices Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Ignoring mount for partition: boot Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Ignoring mount for partition: volumio Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Ignoring mount for partition: volumio_data Oct 30 01:05:45 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Loading plugin "volumio_command_line_client"... Oct 30 01:05:45 volumiopi3 volumio[7169]: info: Loading plugin "upnp"... Oct 30 01:05:45 volumiopi3 volumio[7169]: info: [1730221545998] Starting Upmpd Daemon Oct 30 01:05:45 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "my_music"... Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "mpd"... Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "upnp_browser"... Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "alarm-clock"... Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "airplay_emulation"... Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Starting Shairport Sync Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "last_100"... Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "webradio"... Oct 30 01:05:46 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="philiveroom" Oct 30 01:05:46 volumiopi3 wpa_supplicant[887]: wlan0: Trying to associate with SSID 'philiveroom' Oct 30 01:05:46 volumiopi3 sudo[7195]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:46 volumiopi3 volumio[7169]: info: Loading plugin "i2s_dacs"... Oct 30 01:05:47 volumiopi3 volumio[7169]: info: Loading plugin "volumiodiscovery"... Oct 30 01:05:47 volumiopi3 volumio[7169]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:47 volumiopi3 volumio[7169]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:47 volumiopi3 volumio[7169]: *** WARNING *** For more information see Oct 30 01:05:47 volumiopi3 volumio[7169]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:47 volumiopi3 node[7169]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:47 volumiopi3 volumio[7169]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:47 volumiopi3 volumio[7169]: *** WARNING *** For more information see Oct 30 01:05:47 volumiopi3 node[7169]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:47 volumiopi3 node[7169]: *** WARNING *** For more information see Oct 30 01:05:47 volumiopi3 node[7169]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:05:47 volumiopi3 node[7169]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:05:47 volumiopi3 node[7169]: *** WARNING *** For more information see Oct 30 01:05:47 volumiopi3 volumio[7169]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 01:05:47 volumiopi3 volumio[7169]: info: Discovery: Started advertising with name: VolumioPI3 Oct 30 01:05:47 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:05:47 volumiopi3 volumio[7169]: info: Loading plugin "spop"... Oct 30 01:05:47 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:47+08:00" level=warning msg="failed fetching new endpoint for dealer" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=dealer\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Oct 30 01:05:47 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Oct 30 01:05:47 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=0 ssid="philiveroom" auth_failures=3 duration=46 reason=CONN_FAILED Oct 30 01:05:48 volumiopi3 volumio[7169]: info: Loading plugin "squeezelite_mc"... Oct 30 01:05:48 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:05:48] [connect] Successful connection Oct 30 01:05:48 volumiopi3 volumio[7169]: info: Loading plugin "ytcr"... Oct 30 01:05:50 volumiopi3 go-librespot[1145]: time="2024-10-30T01:05:50+08:00" level=error msg="did not receive last pong from dealer, 90s passed" Oct 30 01:05:50 volumiopi3 go-librespot[1145]: panic: runtime error: invalid memory address or nil pointer dereference Oct 30 01:05:50 volumiopi3 go-librespot[1145]: [signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x43aea8] Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 67 [running]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: panic({0x5a3810, 0x9eea20}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/panic.go:987 +0x414 fp=0x140be50 sp=0x140bdf4 pc=0x4ee28 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.panicmem() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/panic.go:260 +0x4c fp=0x140be5c sp=0x140be50 pc=0x4d5cc Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.sigpanic() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/signal_unix.go:841 +0x26c fp=0x140be78 sp=0x140be5c pc=0x68750 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: nhooyr.io/websocket.(*Conn).writeClose(0x0, 0x3f4, {0x0, 0x0}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:54 +0x14 fp=0x140bee4 sp=0x140be7c pc=0x43aea8 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: nhooyr.io/websocket.(*Conn).closeHandshake(0x0, 0x3f4, {0x0, 0x0}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:37 +0x80 fp=0x140bf24 sp=0x140bee4 pc=0x43accc Oct 30 01:05:50 volumiopi3 go-librespot[1145]: nhooyr.io/websocket.(*Conn).Close(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/go/pkg/mod/nhooyr.io/websocket@v1.8.7/close_notjs.go:31 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/dealer.(*Dealer).pingTicker(0x1077170) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:114 +0x26c fp=0x140bfe4 sp=0x140bf24 pc=0x4785d4 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/dealer.NewDealer.func1() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:57 +0x28 fp=0x140bfec sp=0x140bfe4 pc=0x477d90 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x140bfec sp=0x140bfec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by go-librespot/dealer.NewDealer Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:57 +0x174 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 1 [select, 19 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f84, 0x0, 0x9, 0x18, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x11077e8 sp=0x11077d4 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.selectgo(0x1107a6c, 0x11079b0, 0x0, 0x0, 0x6, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0xb70 fp=0x1107890 sp=0x11077e8 pc=0x64d80 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: main.(*AppPlayer).Run(0x10264b0, 0x1062200) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/player.go:361 +0x1e4 fp=0x1107eac sp=0x1107890 pc=0x53c0d0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: main.(*App).withReusableCredentials(0x11a2040, {0x5abe70, 0x100e570}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:218 +0x660 fp=0x1107f3c sp=0x1107eac pc=0x5382f0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: main.(*App).SpotifyToken(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:159 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: main.main() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/main.go:331 +0x524 fp=0x1107fc0 sp=0x1107f3c pc=0x538cf8 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.main() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:250 +0x268 fp=0x1107fec sp=0x1107fc0 pc=0x52288 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x1107fec sp=0x1107fec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 2 [force gc (idle), 2 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f54, 0xa35150, 0x11, 0x14, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x103cfd8 sp=0x103cfc4 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goparkunlock(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:387 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.forcegchelper() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:305 +0xd4 fp=0x103cfec sp=0x103cfd8 pc=0x525d0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x103cfec sp=0x103cfec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.init.5 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:293 +0x1c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 3 [GC sweep wait]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f54, 0xa35750, 0xc, 0x14, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x103d7c8 sp=0x103d7b4 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goparkunlock(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:387 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.bgsweep(0x1062000) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgcsweep.go:319 +0x104 fp=0x103d7e4 sp=0x103d7c8 pc=0x3c528 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gcenable.func1() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:178 +0x28 fp=0x103d7ec sp=0x103d7e4 pc=0x2cff4 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x103d7ec sp=0x103d7ec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.gcenable Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:178 +0x74 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 4 [GC scavenge wait]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f54, 0xa35a30, 0xd, 0x14, 0x2) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x103dfb4 sp=0x103dfa0 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goparkunlock(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:387 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.(*scavengerState).park(0xa35a30) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgcscavenge.go:400 +0x64 fp=0x103dfc8 sp=0x103dfb4 pc=0x39e1c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.bgscavenge(0x1062000) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgcscavenge.go:633 +0x64 fp=0x103dfe4 sp=0x103dfc8 pc=0x3a560 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gcenable.func2() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:179 +0x28 fp=0x103dfec sp=0x103dfe4 pc=0x2cfa0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x103dfec sp=0x103dfec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.gcenable Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:179 +0xbc Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 5 [finalizer wait, 16 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642e94, 0xa46af4, 0x10, 0x14, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x103c78c sp=0x103c778 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.runfinq() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mfinal.go:193 +0xfc fp=0x103c7ec sp=0x103c78c pc=0x2bed0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x103c7ec sp=0x103c7ec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.createfing Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mfinal.go:163 +0x5c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 6 [IO wait, 122 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f3c, 0x6dc07f40, 0x2, 0x1b, 0x5) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x103e5dc sp=0x103e5c8 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.netpollblock(0x6dc07f34, 0x72, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:527 +0x100 fp=0x103e5f4 sp=0x103e5dc pc=0x49f2c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.runtime_pollWait(0x6dc07f34, 0x72) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:306 +0x54 fp=0x103e608 sp=0x103e5f4 pc=0x800b4 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.(*pollDesc).wait(0x1028f14, 0x72, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x103e61c sp=0x103e608 pc=0xf7db0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.(*pollDesc).waitRead(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:89 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.(*FD).Accept(0x1028f00) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_unix.go:614 +0x2d0 fp=0x103e66c sp=0x103e61c pc=0xfc8d0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net.(*netFD).accept(0x1028f00) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/fd_unix.go:172 +0x20 fp=0x103e6cc sp=0x103e66c pc=0x281ba8 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net.(*TCPListener).accept(0x100e560) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/tcpsock_posix.go:148 +0x20 fp=0x103e6e4 sp=0x103e6cc pc=0x29a540 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net.(*TCPListener).Accept(0x100e560) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/tcpsock.go:297 +0x30 fp=0x103e700 sp=0x103e6e4 pc=0x299504 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net/http.(*onceCloseListener).Accept(0x1090020) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: :1 +0x34 fp=0x103e718 sp=0x103e700 pc=0x427558 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net/http.(*Server).Serve(0x109a000, {0x6ccfb0, 0x100e560}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:3059 +0x344 fp=0x103e7b4 sp=0x103e718 pc=0x403550 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net/http.Serve(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/http/server.go:2581 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: main.(*ApiServer).serve(0x1065a00) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:438 +0x62c fp=0x103e7e4 sp=0x103e7b4 pc=0x532118 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: main.NewApiServer.func1() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:237 +0x28 fp=0x103e7ec sp=0x103e7e4 pc=0x5317d0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x103e7ec sp=0x103e7ec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by main.NewApiServer Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/cmd/daemon/api_server.go:237 +0x1dc Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 12 [GC worker (idle), 122 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642ea0, 0x14325e8, 0x1a, 0x14, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x103ff90 sp=0x103ff7c pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gcBgMarkWorker() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1275 +0x100 fp=0x103ffec sp=0x103ff90 pc=0x2fbb8 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x103ffec sp=0x103ffec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.gcBgMarkStartWorkers Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1199 +0x20 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 13 [GC worker (idle), 19 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642ea0, 0x1432600, 0x1a, 0x14, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x1476790 sp=0x147677c pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gcBgMarkWorker() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1275 +0x100 fp=0x14767ec sp=0x1476790 pc=0x2fbb8 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x14767ec sp=0x14767ec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.gcBgMarkStartWorkers Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1199 +0x20 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 14 [GC worker (idle)]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642ea0, 0x1432618, 0x1a, 0x14, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x1476f90 sp=0x1476f7c pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gcBgMarkWorker() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1275 +0x100 fp=0x1476fec sp=0x1476f90 pc=0x2fbb8 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x1476fec sp=0x1476fec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.gcBgMarkStartWorkers Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1199 +0x20 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 15 [GC worker (idle), 122 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642ea0, 0x1432630, 0x1a, 0x14, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x1477790 sp=0x147777c pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gcBgMarkWorker() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1275 +0x100 fp=0x14777ec sp=0x1477790 pc=0x2fbb8 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x14777ec sp=0x14777ec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by runtime.gcBgMarkStartWorkers Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/mgc.go:1199 +0x20 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 29 [select, 2 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f84, 0x0, 0x9, 0x18, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x1038ea0 sp=0x1038e8c pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.selectgo(0x1038fac, 0x1038f94, 0x0, 0x0, 0x2, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0xb70 fp=0x1038f48 sp=0x1038ea0 pc=0x64d80 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/ap.(*Accesspoint).pongAckTicker(0x122c990) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:301 +0x8c fp=0x1038fe4 sp=0x1038f48 pc=0x455290 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/ap.NewAccesspoint.func1() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:66 +0x28 fp=0x1038fec sp=0x1038fe4 pc=0x453674 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x1038fec sp=0x1038fec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by go-librespot/ap.NewAccesspoint Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:66 +0x190 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 68 [select, 122 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f84, 0x0, 0x9, 0x18, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x1475e94 sp=0x1475e80 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.selectgo(0x1475fb0, 0x1475f84, 0x0, 0x0, 0x2, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0xb70 fp=0x1475f3c sp=0x1475e94 pc=0x64d80 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/player.(*Player).manageLoop(0x130ab00) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/player/player.go:102 +0xd4 fp=0x1475fe4 sp=0x1475f3c pc=0x46922c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/player.NewPlayer.func2() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/player/player.go:86 +0x28 fp=0x1475fec sp=0x1475fe4 pc=0x469094 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x1475fec sp=0x1475fec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by go-librespot/player.NewPlayer Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/player/player.go:86 +0x1bc Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 58 [IO wait, 2 minutes]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f3c, 0x6dc07d6c, 0x2, 0x1b, 0x5) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x1407d88 sp=0x1407d74 pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.netpollblock(0x6dc07d60, 0x72, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:527 +0x100 fp=0x1407da0 sp=0x1407d88 pc=0x49f2c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.runtime_pollWait(0x6dc07d60, 0x72) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/netpoll.go:306 +0x54 fp=0x1407db4 sp=0x1407da0 pc=0x800b4 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.(*pollDesc).wait(0x13d8ba4, 0x72, 0x0) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:84 +0x30 fp=0x1407dc8 sp=0x1407db4 pc=0xf7db0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.(*pollDesc).waitRead(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_poll_runtime.go:89 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: internal/poll.(*FD).Read(0x13d8b90, {0x11e6010, 0x3, 0x3}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/internal/poll/fd_unix.go:167 +0x240 fp=0x1407e18 sp=0x1407dc8 pc=0xf8fbc Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net.(*netFD).Read(0x13d8b90, {0x11e6010, 0x3, 0x3}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/fd_posix.go:55 +0x38 fp=0x1407e44 sp=0x1407e18 pc=0x27faec Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net.(*conn).Read(0x144a078, {0x11e6010, 0x3, 0x3}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/net/net.go:183 +0x48 fp=0x1407e74 sp=0x1407e44 pc=0x290a70 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: net.(*TCPConn).Read(0x144a078, {0x11e6010, 0x3, 0x3}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: :1 +0x44 fp=0x1407e94 sp=0x1407e74 pc=0x2a514c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: io.ReadAtLeast({0x6cb4d4, 0x144a078}, {0x11e6010, 0x3, 0x3}, 0x3) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/io/io.go:332 +0x90 fp=0x1407ec0 sp=0x1407e94 pc=0xf1b18 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: io.ReadFull(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/io/io.go:351 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/ap.(*shannonConn).receivePacket(0x1026210) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/ap/shannon.go:80 +0x124 fp=0x1407f20 sp=0x1407ec0 pc=0x457ddc Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/ap.(*Accesspoint).recvLoop(0x122c990) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:239 +0x58 fp=0x1407fe4 sp=0x1407f20 pc=0x454c1c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/ap.(*Accesspoint).reconnect.func1() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:335 +0x28 fp=0x1407fec sp=0x1407fe4 pc=0x455778 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x1407fec sp=0x1407fec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by go-librespot/ap.(*Accesspoint).reconnect Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/ap/ap.go:335 +0x168 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: goroutine 64 [select]: Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.gopark(0x642f84, 0x0, 0x9, 0x18, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/proc.go:381 +0x100 fp=0x1404dd0 sp=0x1404dbc pc=0x527b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.selectgo(0x1404ed0, 0x1404eb0, 0x0, 0x0, 0x2, 0x1) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/select.go:327 +0xb70 fp=0x1404e78 sp=0x1404dd0 pc=0x64d80 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: github.com/cenkalti/backoff/v4.doRetryNotify[...](0x1404f1c, {0x6cc4c8, 0x11ea060}, 0x0, {0x0, 0x0}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:112 +0x268 fp=0x1404ef4 sp=0x1404e78 pc=0x450c74 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: github.com/cenkalti/backoff/v4.RetryNotifyWithTimer(0x1404f78, {0x6cc4c8, 0x11ea060}, 0x0, {0x0, 0x0}) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:61 +0x6c fp=0x1404f24 sp=0x1404ef4 pc=0x45070c Oct 30 01:05:50 volumiopi3 go-librespot[1145]: github.com/cenkalti/backoff/v4.RetryNotify(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:49 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: github.com/cenkalti/backoff/v4.Retry(...) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/go/pkg/mod/github.com/cenkalti/backoff/v4@v4.2.1/retry.go:38 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/dealer.(*Dealer).recvLoop(0x1077170) Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:191 +0x564 fp=0x1404fe4 sp=0x1404f24 pc=0x478d58 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: go-librespot/dealer.(*Dealer).reconnect.func1() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:241 +0x28 fp=0x1404fec sp=0x1404fe4 pc=0x4792b0 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: runtime.goexit() Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /opt/hostedtoolcache/go/1.20.8/x64/src/runtime/asm_arm.s:831 +0x4 fp=0x1404fec sp=0x1404fec pc=0x84730 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: created by go-librespot/dealer.(*Dealer).reconnect Oct 30 01:05:50 volumiopi3 go-librespot[1145]: /home/runner/work/go-librespot/go-librespot/dealer/dealer.go:241 +0x78 Oct 30 01:05:50 volumiopi3 go-librespot[1145]: Aborted Oct 30 01:05:50 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=134/n/a Oct 30 01:05:50 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:05:51 volumiopi3 volumio[7169]: info: Loading plugin "ytmusic"... Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Loading plugin "outputs"... Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Loading plugin "albumart"... Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Plugin example_plugin is not enabled Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Loading plugin "inputs"... Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Loading plugin "updater_comm"... Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Plugin mpdemulation is not enabled Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Loading plugin "rest_api"... Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Loading plugin "websocket"... Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Starting Socket.io Server version 2.3.0 Oct 30 01:05:52 volumiopi3 volumio[7169]: info: Loading i18n strings for locale en Oct 30 01:05:52 volumiopi3 volumio[7169]: Updating browse sources language Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::initPlayerControls Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: Forking 3 albumart workers Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:52 volumiopi3 volumio[7169]: Express server listening on port 3000 Oct 30 01:05:52 volumiopi3 volumio[7169]: [Metrics] WebUI: 9s 485.42ms Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreStateMachine::resetVolumioState Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreStateMachine::getcurrentVolume Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreStateMachine::pushState Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:52 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:53 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:05:53] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1730221548 101 Oct 30 01:05:53 volumiopi3 volumio[7169]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Reloading queue from file Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Setting Device type: Raspberry PI Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreStateMachine::setRepeat null single undefined Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreStateMachine::pushState Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreStateMachine::setRandom null Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreStateMachine::pushState Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:53 volumiopi3 volumio[7169]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 01:05:53 volumiopi3 volumio[7169]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Completed loading Core Plugins Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Preparing to generate the ALSA configuration file Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Asound.conf file unchanged, so no further update is needed Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Output device has changed, restarting MPD Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Output device has changed, restarting Shairport Sync Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:53 volumiopi3 sudo[7239]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:53 volumiopi3 sudo[7239]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:53 volumiopi3 sudo[7239]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:53 volumiopi3 sudo[7240]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:53 volumiopi3 sudo[7240]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:53 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:05:53 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Oct 30 01:05:53 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: ___________ START PLUGINS ___________ Oct 30 01:05:53 volumiopi3 volumio[7169]: info: ControllerMpd::onStart: Initializing MPD Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Creating MPD Configuration file Oct 30 01:05:53 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:05:53 volumiopi3 go-librespot[7246]: Librespot-go daemon starting... Oct 30 01:05:53 volumiopi3 systemd[1]: Stopping Music Player Daemon... Oct 30 01:05:53 volumiopi3 go-librespot[7246]: time="2024-10-30T01:05:53+08:00" level=info msg="generated new device id: 35a10a08598c66d59558515b611c77230c16f1f0" Oct 30 01:05:53 volumiopi3 go-librespot[7246]: time="2024-10-30T01:05:53+08:00" level=fatal msg="unknown credentials: " Oct 30 01:05:53 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:53 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:53 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:05:53 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:53 volumiopi3 sudo[7256]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:05:53 volumiopi3 volumio[7169]: info: [1730221553580] CoreMusicLibrary::Adding element Media Servers Oct 30 01:05:53 volumiopi3 sudo[7256]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:53 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:53 volumiopi3 sudo[7256]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:53 volumiopi3 sudo[7257]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:05:53 volumiopi3 sudo[7257]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:53 volumiopi3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 30 01:05:53 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:05:53 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:53 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:05:53 volumiopi3 sudo[7264]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:05:53 volumiopi3 sudo[7264]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:53 volumiopi3 sudo[7264]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:53 volumiopi3 volumio[7169]: info: [1730221553927] CoreMusicLibrary::Adding element Last_100 Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:53 volumiopi3 volumio[7169]: info: [1730221553931] CoreMusicLibrary::Adding element Webradio Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:53 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:53 volumiopi3 volumio[7169]: info: Initializing BBC Radios Oct 30 01:05:54 volumiopi3 volumio[7169]: Starting albumart workers Oct 30 01:05:54 volumiopi3 volumio[7169]: Starting albumart workers Oct 30 01:05:54 volumiopi3 volumio[7169]: Starting albumart workers Oct 30 01:05:54 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:05:54 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:05:54 volumiopi3 volumio[7169]: info: Creating Spotify config file Oct 30 01:05:54 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:54 volumiopi3 volumio[7169]: info: [squeezelite_mc] Starting proxy server... Oct 30 01:05:54 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:05:54 volumiopi3 volumio[7169]: info: [1730221554686] CoreMusicLibrary::Adding element YouTube Music Oct 30 01:05:54 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:05:54 volumiopi3 volumio[7169]: Cannot find translation for source YouTube Music Oct 30 01:05:54 volumiopi3 volumio[7169]: info: Volumio Calling Home Oct 30 01:05:54 volumiopi3 volumio[7169]: info: [squeezelite_mc] Proxy server started on port 40847 Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioGetState Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CoreStateMachine::pushState Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CorePlayQueue::getTrack 0 Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CoreCommandRouter::volumioPushState Oct 30 01:05:55 volumiopi3 volumio[7169]: info: [squeezelite_mc] Server discovery started Oct 30 01:05:55 volumiopi3 volumio[7169]: info: [squeezelite_mc] Player finder started Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:05:55 volumiopi3 volumio[7169]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:05:55 volumiopi3 volumio[7169]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 30 01:05:55 volumiopi3 volumio[7169]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:55 volumiopi3 volumio[7169]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 30 01:05:55 volumiopi3 volumio[7169]: at doSend (dgram.js:692:16) Oct 30 01:05:55 volumiopi3 volumio[7169]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 30 01:05:55 volumiopi3 volumio[7169]: at afterDns (dgram.js:638:5) Oct 30 01:05:55 volumiopi3 volumio[7169]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 30 01:05:55 volumiopi3 volumio[7169]: errno: -101, Oct 30 01:05:55 volumiopi3 volumio[7169]: code: 'ENETUNREACH', Oct 30 01:05:55 volumiopi3 volumio[7169]: syscall: 'send', Oct 30 01:05:55 volumiopi3 volumio[7169]: address: '255.255.255.255', Oct 30 01:05:55 volumiopi3 volumio[7169]: port: 3483 Oct 30 01:05:55 volumiopi3 volumio[7169]: } Oct 30 01:05:55 volumiopi3 volumio[7169]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:05:55 volumiopi3 sudo[7318]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 01:04 Oct 30 01:05:55 volumiopi3 sudo[7318]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:05:55 volumiopi3 sudo[7318]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:55 volumiopi3 mpd[7269]: Oct 30 01:05 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:05:55 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:05:55 volumiopi3 sudo[7257]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:55 volumiopi3 sudo[7240]: pam_unix(sudo:session): session closed for user root Oct 30 01:05:56 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:05:56] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Oct 30 01:05:56 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:05:56] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Oct 30 01:05:56 volumiopi3 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:05:56 volumiopi3 systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 01:05:56 volumiopi3 nmbd[746]: [2024/10/30 01:05:56.100737, 0] ../source3/nmbd/nmbd.c:361(reload_interfaces) Oct 30 01:05:56 volumiopi3 nmbd[746]: reload_interfaces: No subnets to listen to. Waiting.. Oct 30 01:05:56 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:56 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:56 volumiopi3 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 30 01:05:56 volumiopi3 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 6. Oct 30 01:05:56 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:05:56 volumiopi3 systemd[1]: Stopped Volumio Backend Module. Oct 30 01:05:56 volumiopi3 systemd[1]: Started Volumio Backend Module. Oct 30 01:05:56 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:05:56 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:05:56 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Oct 30 01:05:56 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:05:56 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:05:56 volumiopi3 go-librespot[7348]: Librespot-go daemon starting... Oct 30 01:05:56 volumiopi3 go-librespot[7348]: time="2024-10-30T01:05:56+08:00" level=info msg="generated new device id: ce61da2366305c986abb6ae5c02fc9f53c48ec8c" Oct 30 01:05:56 volumiopi3 go-librespot[7348]: time="2024-10-30T01:05:56+08:00" level=fatal msg="unknown credentials: " Oct 30 01:05:56 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:05:56 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:05:58 volumiopi3 volumio[7336]: info: ------------------------------------------- Oct 30 01:05:58 volumiopi3 volumio[7336]: info: ----- Volumio3 ---- Oct 30 01:05:58 volumiopi3 volumio[7336]: info: ------------------------------------------- Oct 30 01:05:58 volumiopi3 volumio[7336]: info: ----- System startup ---- Oct 30 01:05:58 volumiopi3 volumio[7336]: info: ------------------------------------------- Oct 30 01:05:58 volumiopi3 volumio[7336]: info: MYVOLUMIO Environment detected Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Plugin folders cleanup Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning into folder /volumio/app/plugins/ Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning category audio_interface Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning category miscellanea Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning category music_service Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning category plugins.json Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning category system_controller Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning category user_interface Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning into folder /data/plugins/ Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Scanning category music_service Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Plugin folders cleanup completed Oct 30 01:05:59 volumiopi3 volumio[7336]: info: ------------------------------------------- Oct 30 01:05:59 volumiopi3 volumio[7336]: info: ----- Core plugins startup ---- Oct 30 01:05:59 volumiopi3 volumio[7336]: info: ------------------------------------------- Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Adding plugin upnp to MyMusic Plugins Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Loading plugins from folder /data/plugins/ Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Loading plugin "system"... Oct 30 01:05:59 volumiopi3 volumio[7336]: info: Loading plugin "appearance"... Oct 30 01:05:59 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:05:59 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Oct 30 01:05:59 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:05:59 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:05:59 volumiopi3 go-librespot[7407]: Librespot-go daemon starting... Oct 30 01:05:59 volumiopi3 go-librespot[7407]: time="2024-10-30T01:05:59+08:00" level=info msg="generated new device id: 32210ed1ea18562ae6922d5472974d0ee51d25df" Oct 30 01:05:59 volumiopi3 go-librespot[7407]: time="2024-10-30T01:05:59+08:00" level=fatal msg="unknown credentials: " Oct 30 01:05:59 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:05:59 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "network"... Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Refreshing Cached IP Addresses Oct 30 01:06:00 volumiopi3 sudo[7415]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 01:06:00 volumiopi3 sudo[7415]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:00 volumiopi3 sudo[7415]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:00 volumiopi3 sudo[7417]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "services"... Oct 30 01:06:00 volumiopi3 sudo[7417]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "alsa_controller"... Oct 30 01:06:00 volumiopi3 sudo[7417]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:00 volumiopi3 sudo[7420]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 30 01:06:00 volumiopi3 sudo[7420]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:00 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "wizard"... Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "networkfs"... Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Starting Udev Watcher for removable devices Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Ignoring mount for partition: boot Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Ignoring mount for partition: volumio Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Ignoring mount for partition: volumio_data Oct 30 01:06:00 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "volumio_command_line_client"... Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "upnp"... Oct 30 01:06:00 volumiopi3 volumio[7336]: info: [1730221560411] Starting Upmpd Daemon Oct 30 01:06:00 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "my_music"... Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "mpd"... Oct 30 01:06:00 volumiopi3 volumio[7336]: info: Loading plugin "upnp_browser"... Oct 30 01:06:00 volumiopi3 sudo[7420]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Loading plugin "alarm-clock"... Oct 30 01:06:01 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:06:01] [connect] Successful connection Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Loading plugin "airplay_emulation"... Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Starting Shairport Sync Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Loading plugin "last_100"... Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Loading plugin "webradio"... Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Loading plugin "i2s_dacs"... Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Loading plugin "volumiodiscovery"... Oct 30 01:06:01 volumiopi3 volumio[7336]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:01 volumiopi3 volumio[7336]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:01 volumiopi3 volumio[7336]: *** WARNING *** For more information see Oct 30 01:06:01 volumiopi3 volumio[7336]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:01 volumiopi3 node[7336]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:01 volumiopi3 volumio[7336]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:01 volumiopi3 volumio[7336]: *** WARNING *** For more information see Oct 30 01:06:01 volumiopi3 node[7336]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:01 volumiopi3 node[7336]: *** WARNING *** For more information see Oct 30 01:06:01 volumiopi3 node[7336]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:01 volumiopi3 node[7336]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:01 volumiopi3 node[7336]: *** WARNING *** For more information see Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Discovery: Started advertising with name: VolumioPI3 Oct 30 01:06:01 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:01 volumiopi3 volumio[7336]: info: Loading plugin "spop"... Oct 30 01:06:02 volumiopi3 volumio[7336]: info: Loading plugin "squeezelite_mc"... Oct 30 01:06:03 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:03 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Oct 30 01:06:03 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:03 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:03 volumiopi3 go-librespot[7427]: Librespot-go daemon starting... Oct 30 01:06:03 volumiopi3 go-librespot[7427]: time="2024-10-30T01:06:03+08:00" level=info msg="generated new device id: 41f9475bd7693de6ff895cb3483cb7fd8d3b1f25" Oct 30 01:06:03 volumiopi3 go-librespot[7427]: time="2024-10-30T01:06:03+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:03 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:03 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:03 volumiopi3 volumio[7336]: info: Loading plugin "ytcr"... Oct 30 01:06:05 volumiopi3 volumio[7336]: info: Loading plugin "ytmusic"... Oct 30 01:06:06 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:06 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Oct 30 01:06:06 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:06 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:06 volumiopi3 go-librespot[7434]: Librespot-go daemon starting... Oct 30 01:06:06 volumiopi3 go-librespot[7434]: time="2024-10-30T01:06:06+08:00" level=info msg="generated new device id: 62e088823adf3c56bfc3c58cf1685164c2b90b5c" Oct 30 01:06:06 volumiopi3 go-librespot[7434]: time="2024-10-30T01:06:06+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:06 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:06 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Loading plugin "outputs"... Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Loading plugin "albumart"... Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Plugin example_plugin is not enabled Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Loading plugin "inputs"... Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Loading plugin "updater_comm"... Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Plugin mpdemulation is not enabled Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Loading plugin "rest_api"... Oct 30 01:06:06 volumiopi3 volumio[7336]: info: Loading plugin "websocket"... Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Starting Socket.io Server version 2.3.0 Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Loading i18n strings for locale en Oct 30 01:06:07 volumiopi3 volumio[7336]: Updating browse sources language Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::initPlayerControls Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: Forking 3 albumart workers Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: Express server listening on port 3000 Oct 30 01:06:07 volumiopi3 volumio[7336]: [Metrics] WebUI: 9s 535.17ms Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreStateMachine::resetVolumioState Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreStateMachine::getcurrentVolume Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreStateMachine::pushState Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Reloading queue from file Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreStateMachine::setRepeat null single undefined Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreStateMachine::pushState Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreStateMachine::setRandom null Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreStateMachine::pushState Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Setting Device type: Raspberry PI Oct 30 01:06:07 volumiopi3 volumio[7336]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 01:06:07 volumiopi3 volumio[7336]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 30 01:06:07 volumiopi3 volumio[7336]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Completed loading Core Plugins Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Preparing to generate the ALSA configuration file Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Asound.conf file unchanged, so no further update is needed Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Output device has changed, restarting MPD Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Output device has changed, restarting Shairport Sync Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:07 volumiopi3 sudo[7478]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:06:07 volumiopi3 sudo[7478]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:07 volumiopi3 sudo[7478]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:07 volumiopi3 sudo[7479]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:06:07 volumiopi3 sudo[7479]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:07 volumiopi3 volumio[7336]: info: ___________ START PLUGINS ___________ Oct 30 01:06:07 volumiopi3 volumio[7336]: info: ControllerMpd::onStart: Initializing MPD Oct 30 01:06:07 volumiopi3 volumio[7336]: info: Creating MPD Configuration file Oct 30 01:06:07 volumiopi3 systemd[1]: Stopping Music Player Daemon... Oct 30 01:06:07 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:06:07 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:07 volumiopi3 volumio[7336]: info: [1730221567883] CoreMusicLibrary::Adding element Media Servers Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:07 volumiopi3 sudo[7488]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:06:07 volumiopi3 sudo[7488]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:07 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:07 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:07 volumiopi3 sudo[7489]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:06:07 volumiopi3 sudo[7489]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:07 volumiopi3 sudo[7488]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:07 volumiopi3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 30 01:06:07 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:06:07 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:06:07 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:06:08 volumiopi3 volumio[7336]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:08 volumiopi3 sudo[7496]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:06:08 volumiopi3 sudo[7496]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:08 volumiopi3 sudo[7496]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:08 volumiopi3 volumio[7336]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:08 volumiopi3 volumio[7336]: info: [1730221568133] CoreMusicLibrary::Adding element Last_100 Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:08 volumiopi3 volumio[7336]: info: [1730221568139] CoreMusicLibrary::Adding element Webradio Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:08 volumiopi3 volumio[7336]: info: Initializing BBC Radios Oct 30 01:06:08 volumiopi3 volumio[7336]: Starting albumart workers Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:08 volumiopi3 volumio[7336]: Starting albumart workers Oct 30 01:06:08 volumiopi3 volumio[7336]: Starting albumart workers Oct 30 01:06:08 volumiopi3 volumio[7336]: info: Creating Spotify config file Oct 30 01:06:08 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:08 volumiopi3 volumio[7336]: info: [squeezelite_mc] Starting proxy server... Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:09 volumiopi3 volumio[7336]: info: [1730221569014] CoreMusicLibrary::Adding element YouTube Music Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:09 volumiopi3 volumio[7336]: Cannot find translation for source YouTube Music Oct 30 01:06:09 volumiopi3 volumio[7336]: info: Volumio Calling Home Oct 30 01:06:09 volumiopi3 volumio[7336]: info: [squeezelite_mc] Proxy server started on port 35245 Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioGetState Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreStateMachine::pushState Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:09 volumiopi3 volumio[7336]: info: [squeezelite_mc] Server discovery started Oct 30 01:06:09 volumiopi3 volumio[7336]: info: [squeezelite_mc] Player finder started Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:09 volumiopi3 volumio[7336]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:09 volumiopi3 volumio[7336]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 30 01:06:09 volumiopi3 volumio[7336]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:06:09 volumiopi3 volumio[7336]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 30 01:06:09 volumiopi3 volumio[7336]: at doSend (dgram.js:692:16) Oct 30 01:06:09 volumiopi3 volumio[7336]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 30 01:06:09 volumiopi3 volumio[7336]: at afterDns (dgram.js:638:5) Oct 30 01:06:09 volumiopi3 volumio[7336]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 30 01:06:09 volumiopi3 volumio[7336]: errno: -101, Oct 30 01:06:09 volumiopi3 volumio[7336]: code: 'ENETUNREACH', Oct 30 01:06:09 volumiopi3 volumio[7336]: syscall: 'send', Oct 30 01:06:09 volumiopi3 volumio[7336]: address: '255.255.255.255', Oct 30 01:06:09 volumiopi3 volumio[7336]: port: 3483 Oct 30 01:06:09 volumiopi3 volumio[7336]: } Oct 30 01:06:09 volumiopi3 volumio[7336]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:06:09 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:09 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Oct 30 01:06:09 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:09 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:09 volumiopi3 go-librespot[7549]: Librespot-go daemon starting... Oct 30 01:06:09 volumiopi3 go-librespot[7549]: time="2024-10-30T01:06:09+08:00" level=info msg="generated new device id: 6c5e6a9b795f84b29e3169f538b2bc59ccf58bb0" Oct 30 01:06:09 volumiopi3 go-librespot[7549]: time="2024-10-30T01:06:09+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:09 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:09 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:10 volumiopi3 sudo[7557]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 01:05 Oct 30 01:06:10 volumiopi3 sudo[7557]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:10 volumiopi3 mpd[7501]: Oct 30 01:06 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:06:10 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:06:10 volumiopi3 sudo[7479]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:10 volumiopi3 sudo[7489]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:10 volumiopi3 sudo[7557]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:10 volumiopi3 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:10 volumiopi3 systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 01:06:10 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:06:10 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:06:10 volumiopi3 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 30 01:06:10 volumiopi3 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7. Oct 30 01:06:10 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:06:10 volumiopi3 systemd[1]: Stopped Volumio Backend Module. Oct 30 01:06:10 volumiopi3 systemd[1]: Started Volumio Backend Module. Oct 30 01:06:10 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:06:12 volumiopi3 volumio[7573]: info: ------------------------------------------- Oct 30 01:06:12 volumiopi3 volumio[7573]: info: ----- Volumio3 ---- Oct 30 01:06:12 volumiopi3 volumio[7573]: info: ------------------------------------------- Oct 30 01:06:12 volumiopi3 volumio[7573]: info: ----- System startup ---- Oct 30 01:06:12 volumiopi3 volumio[7573]: info: ------------------------------------------- Oct 30 01:06:12 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:12 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Oct 30 01:06:12 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:12 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:12 volumiopi3 go-librespot[7593]: Librespot-go daemon starting... Oct 30 01:06:12 volumiopi3 go-librespot[7593]: time="2024-10-30T01:06:12+08:00" level=info msg="generated new device id: c3c827d36eb234b7a4a9e19ea03e4c551910ea84" Oct 30 01:06:12 volumiopi3 go-librespot[7593]: time="2024-10-30T01:06:12+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:12 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:12 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:13 volumiopi3 volumio[7573]: info: MYVOLUMIO Environment detected Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Plugin folders cleanup Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning into folder /volumio/app/plugins/ Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning category audio_interface Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning category miscellanea Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning category music_service Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning category plugins.json Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning category system_controller Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning category user_interface Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning into folder /data/plugins/ Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Scanning category music_service Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Plugin folders cleanup completed Oct 30 01:06:13 volumiopi3 volumio[7573]: info: ------------------------------------------- Oct 30 01:06:13 volumiopi3 volumio[7573]: info: ----- Core plugins startup ---- Oct 30 01:06:13 volumiopi3 volumio[7573]: info: ------------------------------------------- Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Adding plugin upnp to MyMusic Plugins Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Loading plugins from folder /data/plugins/ Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Loading plugin "system"... Oct 30 01:06:13 volumiopi3 volumio[7573]: info: Loading plugin "appearance"... Oct 30 01:06:13 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:06:13] [connect] Successful connection Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "network"... Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Refreshing Cached IP Addresses Oct 30 01:06:14 volumiopi3 sudo[7606]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 01:06:14 volumiopi3 sudo[7606]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:14 volumiopi3 sudo[7606]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:14 volumiopi3 sudo[7608]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 01:06:14 volumiopi3 sudo[7608]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "services"... Oct 30 01:06:14 volumiopi3 sudo[7608]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "alsa_controller"... Oct 30 01:06:14 volumiopi3 sudo[7611]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 30 01:06:14 volumiopi3 sudo[7611]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:14 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "wizard"... Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "networkfs"... Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Starting Udev Watcher for removable devices Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Ignoring mount for partition: boot Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Ignoring mount for partition: volumio Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Ignoring mount for partition: volumio_data Oct 30 01:06:14 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "volumio_command_line_client"... Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "upnp"... Oct 30 01:06:14 volumiopi3 volumio[7573]: info: [1730221574642] Starting Upmpd Daemon Oct 30 01:06:14 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "my_music"... Oct 30 01:06:14 volumiopi3 volumio[7573]: info: Loading plugin "mpd"... Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "upnp_browser"... Oct 30 01:06:15 volumiopi3 sudo[7611]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "alarm-clock"... Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "airplay_emulation"... Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Starting Shairport Sync Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "last_100"... Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "webradio"... Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "i2s_dacs"... Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "volumiodiscovery"... Oct 30 01:06:15 volumiopi3 volumio[7573]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:15 volumiopi3 node[7573]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:15 volumiopi3 volumio[7573]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:15 volumiopi3 node[7573]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:15 volumiopi3 volumio[7573]: *** WARNING *** For more information see Oct 30 01:06:15 volumiopi3 node[7573]: *** WARNING *** For more information see Oct 30 01:06:15 volumiopi3 volumio[7573]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:15 volumiopi3 node[7573]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:15 volumiopi3 volumio[7573]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:15 volumiopi3 node[7573]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:15 volumiopi3 volumio[7573]: *** WARNING *** For more information see Oct 30 01:06:15 volumiopi3 node[7573]: *** WARNING *** For more information see Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Discovery: Started advertising with name: VolumioPI3 Oct 30 01:06:15 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:15 volumiopi3 volumio[7573]: info: Loading plugin "spop"... Oct 30 01:06:16 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:16 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Oct 30 01:06:16 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:16 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:16 volumiopi3 go-librespot[7618]: Librespot-go daemon starting... Oct 30 01:06:16 volumiopi3 go-librespot[7618]: time="2024-10-30T01:06:16+08:00" level=info msg="generated new device id: 0cd2dfceb7cb04199a820c09c8ffaa42a05dbf7c" Oct 30 01:06:16 volumiopi3 go-librespot[7618]: time="2024-10-30T01:06:16+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:16 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:16 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:16 volumiopi3 volumio[7573]: info: Loading plugin "squeezelite_mc"... Oct 30 01:06:17 volumiopi3 volumio[7573]: info: Loading plugin "ytcr"... Oct 30 01:06:19 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:19 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Oct 30 01:06:19 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:19 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:19 volumiopi3 go-librespot[7625]: Librespot-go daemon starting... Oct 30 01:06:19 volumiopi3 go-librespot[7625]: time="2024-10-30T01:06:19+08:00" level=info msg="generated new device id: bd86f0a285c4ad0a21d4973d74f430347e44d110" Oct 30 01:06:19 volumiopi3 go-librespot[7625]: time="2024-10-30T01:06:19+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:19 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:19 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:19 volumiopi3 volumio[7573]: info: Loading plugin "ytmusic"... Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Loading plugin "outputs"... Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Loading plugin "albumart"... Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Plugin example_plugin is not enabled Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Loading plugin "inputs"... Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Loading plugin "updater_comm"... Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Plugin mpdemulation is not enabled Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Loading plugin "rest_api"... Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Loading plugin "websocket"... Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Starting Socket.io Server version 2.3.0 Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Loading i18n strings for locale en Oct 30 01:06:21 volumiopi3 volumio[7573]: Updating browse sources language Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::initPlayerControls Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: Forking 3 albumart workers Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: Express server listening on port 3000 Oct 30 01:06:21 volumiopi3 volumio[7573]: [Metrics] WebUI: 9s 546.06ms Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreStateMachine::resetVolumioState Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreStateMachine::getcurrentVolume Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreStateMachine::pushState Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Reloading queue from file Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreStateMachine::setRepeat null single undefined Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreStateMachine::pushState Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreStateMachine::setRandom null Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreStateMachine::pushState Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Setting Device type: Raspberry PI Oct 30 01:06:21 volumiopi3 volumio[7573]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 01:06:21 volumiopi3 volumio[7573]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 30 01:06:21 volumiopi3 volumio[7573]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Completed loading Core Plugins Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Preparing to generate the ALSA configuration file Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Asound.conf file unchanged, so no further update is needed Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Output device has changed, restarting MPD Oct 30 01:06:21 volumiopi3 volumio[7573]: info: Output device has changed, restarting Shairport Sync Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:21 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:21 volumiopi3 sudo[7669]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:06:21 volumiopi3 sudo[7669]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:21 volumiopi3 sudo[7669]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:21 volumiopi3 sudo[7670]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:06:21 volumiopi3 sudo[7670]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:22 volumiopi3 volumio[7573]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:22 volumiopi3 volumio[7573]: info: ___________ START PLUGINS ___________ Oct 30 01:06:22 volumiopi3 systemd[1]: Stopping Music Player Daemon... Oct 30 01:06:22 volumiopi3 volumio[7573]: info: ControllerMpd::onStart: Initializing MPD Oct 30 01:06:22 volumiopi3 volumio[7573]: info: Creating MPD Configuration file Oct 30 01:06:22 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:06:22 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:22 volumiopi3 volumio[7573]: info: [1730221582114] CoreMusicLibrary::Adding element Media Servers Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:22 volumiopi3 sudo[7680]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:06:22 volumiopi3 sudo[7680]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:22 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:22 volumiopi3 sudo[7679]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:06:22 volumiopi3 sudo[7679]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:22 volumiopi3 sudo[7679]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:22 volumiopi3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 30 01:06:22 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:06:22 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:06:22 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:06:22 volumiopi3 volumio[7573]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:22 volumiopi3 sudo[7686]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:06:22 volumiopi3 sudo[7686]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:22 volumiopi3 sudo[7686]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:22 volumiopi3 volumio[7573]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:22 volumiopi3 volumio[7573]: info: [1730221582399] CoreMusicLibrary::Adding element Last_100 Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:22 volumiopi3 volumio[7573]: info: [1730221582404] CoreMusicLibrary::Adding element Webradio Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:22 volumiopi3 volumio[7573]: info: Initializing BBC Radios Oct 30 01:06:22 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:22 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Oct 30 01:06:22 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:22 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:22 volumiopi3 go-librespot[7694]: Librespot-go daemon starting... Oct 30 01:06:22 volumiopi3 go-librespot[7694]: time="2024-10-30T01:06:22+08:00" level=info msg="generated new device id: bd405a89fd11e3bfe6a7ae23edc8bb4579da0d1e" Oct 30 01:06:22 volumiopi3 go-librespot[7694]: time="2024-10-30T01:06:22+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:22 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:22 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:22 volumiopi3 volumio[7573]: Starting albumart workers Oct 30 01:06:22 volumiopi3 volumio[7573]: Starting albumart workers Oct 30 01:06:22 volumiopi3 volumio[7573]: info: Creating Spotify config file Oct 30 01:06:22 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:22 volumiopi3 volumio[7573]: Starting albumart workers Oct 30 01:06:22 volumiopi3 volumio[7573]: info: [squeezelite_mc] Starting proxy server... Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:23 volumiopi3 volumio[7573]: info: [1730221583011] CoreMusicLibrary::Adding element YouTube Music Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:23 volumiopi3 volumio[7573]: Cannot find translation for source YouTube Music Oct 30 01:06:23 volumiopi3 volumio[7573]: info: Volumio Calling Home Oct 30 01:06:23 volumiopi3 volumio[7573]: info: [squeezelite_mc] Proxy server started on port 35611 Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioGetState Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreStateMachine::pushState Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:23 volumiopi3 volumio[7573]: info: [squeezelite_mc] Server discovery started Oct 30 01:06:23 volumiopi3 volumio[7573]: info: [squeezelite_mc] Player finder started Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:23 volumiopi3 volumio[7573]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:23 volumiopi3 volumio[7573]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 30 01:06:23 volumiopi3 volumio[7573]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:06:23 volumiopi3 volumio[7573]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 30 01:06:23 volumiopi3 volumio[7573]: at doSend (dgram.js:692:16) Oct 30 01:06:23 volumiopi3 volumio[7573]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 30 01:06:23 volumiopi3 volumio[7573]: at afterDns (dgram.js:638:5) Oct 30 01:06:23 volumiopi3 volumio[7573]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 30 01:06:23 volumiopi3 volumio[7573]: errno: -101, Oct 30 01:06:23 volumiopi3 volumio[7573]: code: 'ENETUNREACH', Oct 30 01:06:23 volumiopi3 volumio[7573]: syscall: 'send', Oct 30 01:06:23 volumiopi3 volumio[7573]: address: '255.255.255.255', Oct 30 01:06:23 volumiopi3 volumio[7573]: port: 3483 Oct 30 01:06:23 volumiopi3 volumio[7573]: } Oct 30 01:06:23 volumiopi3 volumio[7573]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:06:24 volumiopi3 sudo[7747]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 01:05 Oct 30 01:06:24 volumiopi3 sudo[7747]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:24 volumiopi3 sudo[7747]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:24 volumiopi3 mpd[7691]: Oct 30 01:06 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:06:24 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:06:24 volumiopi3 sudo[7680]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:24 volumiopi3 sudo[7670]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:24 volumiopi3 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:24 volumiopi3 systemd[1]: volumio.service: Failed with result 'exit-code'. Oct 30 01:06:24 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:06:24 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:06:24 volumiopi3 systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Oct 30 01:06:24 volumiopi3 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 8. Oct 30 01:06:24 volumiopi3 systemd[1]: Stopped Volumio Backend Module. Oct 30 01:06:24 volumiopi3 systemd[1]: Started Volumio Backend Module. Oct 30 01:06:24 volumiopi3 systemd[1]: Started dynamicswap service. Oct 30 01:06:24 volumiopi3 systemd[1]: dynamicswap.service: Succeeded. Oct 30 01:06:25 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:25 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Oct 30 01:06:25 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:25 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:25 volumiopi3 go-librespot[7775]: Librespot-go daemon starting... Oct 30 01:06:25 volumiopi3 go-librespot[7775]: time="2024-10-30T01:06:25+08:00" level=info msg="generated new device id: c5e76bab06ebd1967f1b3a2420ed961c8a7b0a24" Oct 30 01:06:25 volumiopi3 go-librespot[7775]: time="2024-10-30T01:06:25+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:25 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:25 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:26 volumiopi3 volumio[7762]: info: ------------------------------------------- Oct 30 01:06:26 volumiopi3 volumio[7762]: info: ----- Volumio3 ---- Oct 30 01:06:26 volumiopi3 volumio[7762]: info: ------------------------------------------- Oct 30 01:06:26 volumiopi3 volumio[7762]: info: ----- System startup ---- Oct 30 01:06:26 volumiopi3 volumio[7762]: info: ------------------------------------------- Oct 30 01:06:27 volumiopi3 volumio[7762]: info: MYVOLUMIO Environment detected Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Plugin folders cleanup Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning into folder /volumio/app/plugins/ Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning category audio_interface Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning category miscellanea Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning category music_service Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning category plugins.json Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning category system_controller Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning category user_interface Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning into folder /data/plugins/ Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Scanning category music_service Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Plugin folders cleanup completed Oct 30 01:06:27 volumiopi3 volumio[7762]: info: ------------------------------------------- Oct 30 01:06:27 volumiopi3 volumio[7762]: info: ----- Core plugins startup ---- Oct 30 01:06:27 volumiopi3 volumio[7762]: info: ------------------------------------------- Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Loading plugins from folder /volumio/app/plugins/ Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Adding plugin upnp to MyMusic Plugins Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Adding plugin airplay_emulation to MyMusic Plugins Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Adding plugin upnp_browser to MyMusic Plugins Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Loading plugins from folder /data/plugins/ Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Loading plugin "system"... Oct 30 01:06:27 volumiopi3 volumio[7762]: info: Loading plugin "appearance"... Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "network"... Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Refreshing Cached IP Addresses Oct 30 01:06:28 volumiopi3 sudo[7796]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 30 01:06:28 volumiopi3 sudo[7796]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:28 volumiopi3 sudo[7796]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:28 volumiopi3 sudo[7798]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "services"... Oct 30 01:06:28 volumiopi3 sudo[7798]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "alsa_controller"... Oct 30 01:06:28 volumiopi3 sudo[7798]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:28 volumiopi3 sudo[7801]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Oct 30 01:06:28 volumiopi3 sudo[7801]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:28 volumiopi3 volumio-remote-updater[638]: [2024-10-30 01:06:28] [connect] Successful connection Oct 30 01:06:28 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "wizard"... Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "networkfs"... Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Starting Udev Watcher for removable devices Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Ignoring mount for partition: boot Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Ignoring mount for partition: volumio Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Ignoring mount for partition: volumio_data Oct 30 01:06:28 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "volumio_command_line_client"... Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "upnp"... Oct 30 01:06:28 volumiopi3 volumio[7762]: info: [1730221588666] Starting Upmpd Daemon Oct 30 01:06:28 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "my_music"... Oct 30 01:06:28 volumiopi3 volumio[7762]: info: Loading plugin "mpd"... Oct 30 01:06:28 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:28 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Oct 30 01:06:28 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:28 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:28 volumiopi3 go-librespot[7806]: Librespot-go daemon starting... Oct 30 01:06:28 volumiopi3 go-librespot[7806]: time="2024-10-30T01:06:28+08:00" level=info msg="generated new device id: d952005cb6095d005a1a62b591bf2ca7069dfad6" Oct 30 01:06:28 volumiopi3 go-librespot[7806]: time="2024-10-30T01:06:28+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:28 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:28 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "upnp_browser"... Oct 30 01:06:29 volumiopi3 sudo[7801]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "alarm-clock"... Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "airplay_emulation"... Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Starting Shairport Sync Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "last_100"... Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "webradio"... Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "i2s_dacs"... Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "volumiodiscovery"... Oct 30 01:06:29 volumiopi3 volumio[7762]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:29 volumiopi3 volumio[7762]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:29 volumiopi3 volumio[7762]: *** WARNING *** For more information see Oct 30 01:06:29 volumiopi3 volumio[7762]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:29 volumiopi3 node[7762]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:29 volumiopi3 volumio[7762]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:29 volumiopi3 volumio[7762]: *** WARNING *** For more information see Oct 30 01:06:29 volumiopi3 node[7762]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:29 volumiopi3 node[7762]: *** WARNING *** For more information see Oct 30 01:06:29 volumiopi3 node[7762]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Oct 30 01:06:29 volumiopi3 node[7762]: *** WARNING *** Please fix your application to use the native API of Avahi! Oct 30 01:06:29 volumiopi3 node[7762]: *** WARNING *** For more information see Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Applying required configuration parameters for plugin volumiodiscovery Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Discovery: Started advertising with name: VolumioPI3 Oct 30 01:06:29 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 30 01:06:29 volumiopi3 volumio[7762]: info: Loading plugin "spop"... Oct 30 01:06:30 volumiopi3 volumio[7762]: info: Loading plugin "squeezelite_mc"... Oct 30 01:06:31 volumiopi3 volumio[7762]: info: Loading plugin "ytcr"... Oct 30 01:06:32 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:32 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Oct 30 01:06:32 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:32 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:32 volumiopi3 go-librespot[7815]: Librespot-go daemon starting... Oct 30 01:06:32 volumiopi3 go-librespot[7815]: time="2024-10-30T01:06:32+08:00" level=info msg="generated new device id: c6d922b26628385359663e75e9fd966caa214e26" Oct 30 01:06:32 volumiopi3 go-librespot[7815]: time="2024-10-30T01:06:32+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:32 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:32 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:32 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-SSID-REENABLED id=0 ssid="philiveroom" Oct 30 01:06:32 volumiopi3 wpa_supplicant[887]: wlan0: Trying to associate with SSID 'philiveroom' Oct 30 01:06:33 volumiopi3 dhcpcd[898]: wlan0: carrier acquired Oct 30 01:06:33 volumiopi3 wpa_supplicant[887]: wlan0: Associated with 20:6a:94:bb:c1:66 Oct 30 01:06:33 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-CONNECTED - Connection to 20:6a:94:bb:c1:66 completed [id=0 id_str=] Oct 30 01:06:33 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Oct 30 01:06:33 volumiopi3 wpa_supplicant[887]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=TW Oct 30 01:06:33 volumiopi3 dhcpcd[898]: wlan0: IAID eb:5c:5b:1d Oct 30 01:06:33 volumiopi3 dhcpcd[898]: wlan0: probing address 192.168.1.111/24 Oct 30 01:06:33 volumiopi3 dhcpcd[898]: wlan0: carrier lost Oct 30 01:06:33 volumiopi3 dhcpcd[898]: wlan0: carrier acquired Oct 30 01:06:33 volumiopi3 dhcpcd[898]: wlan0: IAID eb:5c:5b:1d Oct 30 01:06:33 volumiopi3 dhcpcd[898]: wlan0: probing address 192.168.1.111/24 Oct 30 01:06:33 volumiopi3 volumio[7762]: info: Loading plugin "ytmusic"... Oct 30 01:06:34 volumiopi3 dhcpcd[898]: wlan0: soliciting an IPv6 router Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Loading plugin "outputs"... Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Loading plugin "albumart"... Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Plugin example_plugin is not enabled Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Loading plugin "inputs"... Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Loading plugin "updater_comm"... Oct 30 01:06:35 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:35 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Oct 30 01:06:35 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Plugin mpdemulation is not enabled Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Loading plugin "rest_api"... Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Loading plugin "websocket"... Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Starting Socket.io Server version 2.3.0 Oct 30 01:06:35 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:35 volumiopi3 go-librespot[7849]: Librespot-go daemon starting... Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Loading i18n strings for locale en Oct 30 01:06:35 volumiopi3 volumio[7762]: Updating browse sources language Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:35 volumiopi3 go-librespot[7849]: time="2024-10-30T01:06:35+08:00" level=info msg="generated new device id: e94f1647baa217afd1dd72f2c814c9dba99c60cc" Oct 30 01:06:35 volumiopi3 go-librespot[7849]: time="2024-10-30T01:06:35+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:35 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:35 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::initPlayerControls Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: Forking 3 albumart workers Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: Express server listening on port 3000 Oct 30 01:06:35 volumiopi3 volumio[7762]: [Metrics] WebUI: 9s 577.15ms Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreStateMachine::resetVolumioState Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreStateMachine::getcurrentVolume Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreStateMachine::pushState Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Reloading queue from file Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreStateMachine::setRepeat null single undefined Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreStateMachine::pushState Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreStateMachine::setRandom null Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreStateMachine::pushState Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:35 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Setting Device type: Raspberry PI Oct 30 01:06:35 volumiopi3 volumio[7762]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Oct 30 01:06:35 volumiopi3 volumio[7762]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Oct 30 01:06:35 volumiopi3 volumio[7762]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Completed loading Core Plugins Oct 30 01:06:35 volumiopi3 volumio[7762]: info: Preparing to generate the ALSA configuration file Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Asound.conf file unchanged, so no further update is needed Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Output device has changed, restarting MPD Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Output device has changed, restarting Shairport Sync Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:36 volumiopi3 sudo[7886]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:06:36 volumiopi3 sudo[7886]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:36 volumiopi3 sudo[7888]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:06:36 volumiopi3 sudo[7888]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:36 volumiopi3 sudo[7886]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:36 volumiopi3 volumio[7762]: info: ___________ START PLUGINS ___________ Oct 30 01:06:36 volumiopi3 volumio[7762]: info: ControllerMpd::onStart: Initializing MPD Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Creating MPD Configuration file Oct 30 01:06:36 volumiopi3 systemd[1]: Stopping Music Player Daemon... Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:36 volumiopi3 sudo[7894]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 30 01:06:36 volumiopi3 volumio[7762]: info: [1730221596244] CoreMusicLibrary::Adding element Media Servers Oct 30 01:06:36 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:06:36 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:36 volumiopi3 sudo[7894]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:36 volumiopi3 sudo[7894]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:36 volumiopi3 sudo[7896]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 30 01:06:36 volumiopi3 sudo[7896]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:36 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:06:36 volumiopi3 systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Oct 30 01:06:36 volumiopi3 systemd[1]: mpd.service: Succeeded. Oct 30 01:06:36 volumiopi3 systemd[1]: Stopped Music Player Daemon. Oct 30 01:06:36 volumiopi3 systemd[1]: Starting Music Player Daemon... Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:36 volumiopi3 volumio[7762]: info: [1730221596508] CoreMusicLibrary::Adding element Last_100 Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:36 volumiopi3 volumio[7762]: info: [1730221596512] CoreMusicLibrary::Adding element Webradio Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:36 volumiopi3 sudo[7903]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Oct 30 01:06:36 volumiopi3 sudo[7903]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Initializing BBC Radios Oct 30 01:06:36 volumiopi3 sudo[7903]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 30 01:06:36 volumiopi3 volumio[7762]: info: Creating Spotify config file Oct 30 01:06:36 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:36 volumiopi3 volumio[7762]: Starting albumart workers Oct 30 01:06:36 volumiopi3 volumio[7762]: info: [squeezelite_mc] Starting proxy server... Oct 30 01:06:36 volumiopi3 volumio[7762]: Starting albumart workers Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 30 01:06:37 volumiopi3 volumio[7762]: info: [1730221597008] CoreMusicLibrary::Adding element YouTube Music Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 30 01:06:37 volumiopi3 volumio[7762]: Cannot find translation for source YouTube Music Oct 30 01:06:37 volumiopi3 volumio[7762]: info: Volumio Calling Home Oct 30 01:06:37 volumiopi3 volumio[7762]: Starting albumart workers Oct 30 01:06:37 volumiopi3 volumio[7762]: info: [squeezelite_mc] Proxy server started on port 36113 Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioRetrievevolume Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioGetState Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreStateMachine::pushState Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CorePlayQueue::getTrack 0 Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::volumioPushState Oct 30 01:06:37 volumiopi3 volumio[7762]: info: [squeezelite_mc] Server discovery started Oct 30 01:06:37 volumiopi3 volumio[7762]: info: [squeezelite_mc] Player finder started Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 30 01:06:37 volumiopi3 volumio[7762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 30 01:06:37 volumiopi3 volumio[7762]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Oct 30 01:06:37 volumiopi3 volumio[7762]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:06:37 volumiopi3 volumio[7762]: Error: send ENETUNREACH 255.255.255.255:3483 Oct 30 01:06:37 volumiopi3 volumio[7762]: at doSend (dgram.js:692:16) Oct 30 01:06:37 volumiopi3 volumio[7762]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Oct 30 01:06:37 volumiopi3 volumio[7762]: at afterDns (dgram.js:638:5) Oct 30 01:06:37 volumiopi3 volumio[7762]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Oct 30 01:06:37 volumiopi3 volumio[7762]: errno: -101, Oct 30 01:06:37 volumiopi3 volumio[7762]: code: 'ENETUNREACH', Oct 30 01:06:37 volumiopi3 volumio[7762]: syscall: 'send', Oct 30 01:06:37 volumiopi3 volumio[7762]: address: '255.255.255.255', Oct 30 01:06:37 volumiopi3 volumio[7762]: port: 3483 Oct 30 01:06:37 volumiopi3 volumio[7762]: } Oct 30 01:06:37 volumiopi3 volumio[7762]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 30 01:06:38 volumiopi3 sudo[7957]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-30 01:05 Oct 30 01:06:38 volumiopi3 sudo[7957]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 30 01:06:38 volumiopi3 dhcpcd[898]: wlan0: using static address 192.168.1.111/24 Oct 30 01:06:38 volumiopi3 avahi-daemon[645]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.111. Oct 30 01:06:38 volumiopi3 avahi-daemon[645]: New relevant interface wlan0.IPv4 for mDNS. Oct 30 01:06:38 volumiopi3 dhcpcd[898]: wlan0: adding route to 192.168.1.0/24 Oct 30 01:06:38 volumiopi3 dhcpcd[898]: wlan0: adding default route via 192.168.1.1 Oct 30 01:06:38 volumiopi3 avahi-daemon[645]: Registering new address record for 192.168.1.111 on wlan0.IPv4. Oct 30 01:06:38 volumiopi3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 30 01:06:38 volumiopi3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Oct 30 01:06:38 volumiopi3 systemd[1]: Stopped go-librespot Daemon. Oct 30 01:06:38 volumiopi3 mpd[7908]: Oct 30 01:06 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 30 01:06:38 volumiopi3 systemd[1]: Started go-librespot Daemon. Oct 30 01:06:38 volumiopi3 go-librespot[7976]: Librespot-go daemon starting... Oct 30 01:06:38 volumiopi3 systemd[1]: Started Music Player Daemon. Oct 30 01:06:38 volumiopi3 sudo[7888]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:38 volumiopi3 sudo[7896]: pam_unix(sudo:session): session closed for user root Oct 30 01:06:38 volumiopi3 go-librespot[7976]: time="2024-10-30T01:06:38+08:00" level=info msg="generated new device id: e0a420e8583f2f0116acb20d2cf10840c6513507" Oct 30 01:06:38 volumiopi3 go-librespot[7976]: time="2024-10-30T01:06:38+08:00" level=fatal msg="unknown credentials: " Oct 30 01:06:38 volumiopi3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 30 01:06:38 volumiopi3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:01:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e0a6dc7e914e3fb93cbf2123f2f73eac"