-- Logs begin at Sun 2025-03-16 20:28:25 EDT, end at Sun 2025-03-16 21:01:23 EDT. -- Mar 16 21:00:01 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 515. Mar 16 21:00:02 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:02 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:02 volumio go-librespot[16621]: Librespot-go daemon starting... Mar 16 21:00:02 volumio go-librespot[16621]: time="2025-03-16T21:00:02-04:00" level=info msg="generated new device id: 004b294830daa2a7b1671d73b93b17cb0377698b" Mar 16 21:00:02 volumio go-librespot[16621]: time="2025-03-16T21:00:02-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:02 volumio go-librespot[16621]: time="2025-03-16T21:00:02-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:03 volumio volumio[16540]: info: Loading plugin "outputs"... Mar 16 21:00:03 volumio volumio[16540]: info: Loading plugin "albumart"... Mar 16 21:00:03 volumio volumio[16540]: info: Plugin example_plugin is not enabled Mar 16 21:00:03 volumio volumio[16540]: info: Loading plugin "inputs"... Mar 16 21:00:03 volumio volumio[16540]: info: Loading plugin "updater_comm"... Mar 16 21:00:04 volumio volumio[16540]: info: Plugin mpdemulation is not enabled Mar 16 21:00:04 volumio volumio[16540]: info: Loading plugin "rest_api"... Mar 16 21:00:04 volumio volumio[16540]: info: Loading plugin "websocket"... Mar 16 21:00:04 volumio volumio[16540]: info: Starting Socket.io Server version 2.3.0 Mar 16 21:00:04 volumio volumio[16540]: info: Loading plugin "volusonic"... Mar 16 21:00:04 volumio volumio[16540]: Forking 3 albumart workers Mar 16 21:00:05 volumio volumio[16540]: info: Applying required configuration parameters for plugin volusonic Mar 16 21:00:05 volumio volumio[16540]: info: Plugin touch_display is not enabled Mar 16 21:00:05 volumio volumio[16540]: info: Loading i18n strings for locale en Mar 16 21:00:05 volumio volumio[16540]: Updating browse sources language Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:05 volumio volumio[16540]: Starting albumart workers Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:05 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::initPlayerControls Mar 16 21:00:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 516. Mar 16 21:00:05 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:05 volumio volumio[16540]: Express server listening on port 3000 Mar 16 21:00:05 volumio volumio[16540]: [Metrics] WebUI: 12s 896.05ms Mar 16 21:00:05 volumio volumio[16540]: Starting albumart workers Mar 16 21:00:05 volumio volumio[16540]: Starting albumart workers Mar 16 21:00:05 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:05 volumio go-librespot[16657]: Librespot-go daemon starting... Mar 16 21:00:05 volumio volumio[16540]: info: CoreStateMachine::resetVolumioState Mar 16 21:00:05 volumio volumio[16540]: info: CoreStateMachine::getcurrentVolume Mar 16 21:00:05 volumio volumio[16540]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:05 volumio go-librespot[16657]: time="2025-03-16T21:00:05-04:00" level=info msg="generated new device id: 62f59423fef3afdb645075fe12b567d203e406d4" Mar 16 21:00:05 volumio go-librespot[16657]: time="2025-03-16T21:00:05-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:05 volumio go-librespot[16657]: time="2025-03-16T21:00:05-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:05 volumio volumio[16540]: info: Volumio Network Manager: Network status updated: 0 Mar 16 21:00:05 volumio volumio[16540]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Mar 16 21:00:05 volumio volumio[16540]: wlan0 Interface doesn't support scanning : Device or resource busy Mar 16 21:00:05 volumio volumio[16540]: info: Cannot use regular scanning, forcing with ap-force Mar 16 21:00:05 volumio sudo[16669]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Mar 16 21:00:05 volumio sudo[16669]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:06 volumio sudo[16669]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:06 volumio sudo[16707]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:00:06 volumio sudo[16707]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:06 volumio sudo[16712]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:00:06 volumio sudo[16712]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:06 volumio sudo[16712]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:06 volumio sudo[16707]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:06 volumio volumio[16540]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:06 volumio volumio[16540]: info: Reloading queue from file Mar 16 21:00:06 volumio volumio[16540]: info: CoreStateMachine::setRepeat null single undefined Mar 16 21:00:06 volumio volumio[16540]: info: CoreStateMachine::pushState Mar 16 21:00:06 volumio volumio[16540]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:06 volumio volumio[16540]: info: CoreStateMachine::setRandom true Mar 16 21:00:06 volumio volumio[16540]: info: CoreStateMachine::pushState Mar 16 21:00:06 volumio volumio[16540]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:06 volumio volumio[16540]: info: Setting Device type: Raspberry PI Mar 16 21:00:06 volumio volumio[16540]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 16 21:00:06 volumio volumio[16540]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 16 21:00:06 volumio volumio[16540]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 16 21:00:06 volumio volumio[16540]: info: Completed loading Core Plugins Mar 16 21:00:06 volumio volumio[16540]: info: Preparing to generate the ALSA configuration file Mar 16 21:00:06 volumio volumio[16540]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:06 volumio volumio[16540]: info: CoreStateMachine::pushState Mar 16 21:00:06 volumio volumio[16540]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:06 volumio volumio[16540]: info: CoreStateMachine::updateTrackBlock Mar 16 21:00:06 volumio volumio[16540]: info: CorePlayQueue::getTrackBlock Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:06 volumio volumio[16540]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 16 21:00:06 volumio volumio[16540]: info: Reading ALSA contributions from plugins. Mar 16 21:00:06 volumio volumio[16540]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:06 volumio sudo[16724]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 16 21:00:06 volumio sudo[16724]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:06 volumio volumio[16540]: info: Asound.conf file unchanged, so no further update is needed Mar 16 21:00:06 volumio volumio[16540]: info: Output device has changed, restarting MPD Mar 16 21:00:06 volumio sudo[16724]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:06 volumio sudo[16728]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:00:06 volumio sudo[16728]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:06 volumio volumio[16540]: info: Output device has changed, restarting Shairport Sync Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:06 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:06 volumio sudo[16728]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:06 volumio sudo[16731]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:00:06 volumio sudo[16731]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:07 volumio systemd[1]: Stopping Music Player Daemon... Mar 16 21:00:07 volumio volumio[16540]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:07 volumio volumio[16540]: info: ___________ START PLUGINS ___________ Mar 16 21:00:07 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:00:07 volumio volumio[16540]: info: ControllerMpd::onStart: Initializing MPD Mar 16 21:00:07 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:00:07 volumio volumio[16540]: info: Creating MPD Configuration file Mar 16 21:00:07 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:00:07 volumio sudo[16748]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:00:07 volumio sudo[16748]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:07 volumio sudo[16748]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:07 volumio volumio[16540]: info: [1742173207153] CoreMusicLibrary::Adding element Media Servers Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:07 volumio sudo[16757]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:00:07 volumio sudo[16757]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:07 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Mar 16 21:00:07 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:00:07 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:00:07 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:00:07 volumio volumio[16540]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:07 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:07 volumio volumio[16540]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:07 volumio volumio[16540]: info: [1742173207361] CoreMusicLibrary::Adding element Last_100 Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:07 volumio volumio[16540]: info: [1742173207365] CoreMusicLibrary::Adding element Webradio Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:07 volumio volumio[16540]: info: Initializing BBC Radios Mar 16 21:00:07 volumio volumio[16540]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:07 volumio sudo[16772]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 21:00:07 volumio sudo[16772]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:07 volumio sudo[16772]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:07 volumio volumio[16540]: info: Creating Spotify config file Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:07 volumio volumio[16540]: info: [squeezelite_mc] Starting proxy server... Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:07 volumio volumio[16540]: info: [1742173207679] CoreMusicLibrary::Adding element YouTube2 Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:07 volumio volumio[16540]: Cannot find translation for source YouTube2 Mar 16 21:00:07 volumio volumio[16540]: info: Loading i18n strings for locale en Mar 16 21:00:07 volumio volumio[16540]: Updating browse sources language Mar 16 21:00:07 volumio volumio[16540]: Cannot find translation for source YouTube2 Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:07 volumio volumio[16540]: Cannot find translation for source YouTube2 Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:07 volumio volumio[16540]: info: [1742173207748] CoreMusicLibrary::Adding element Volusonic Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:07 volumio volumio[16540]: Cannot find translation for source YouTube2 Mar 16 21:00:07 volumio volumio[16540]: Cannot find translation for source Volusonic Mar 16 21:00:07 volumio volumio[16540]: info: Volumio Calling Home Mar 16 21:00:07 volumio volumio[16540]: info: [squeezelite_mc] Proxy server started on port 42177 Mar 16 21:00:07 volumio volumio[16540]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:07 volumio volumio[16540]: Unhandled rejection Error: No sockets available, cannot start. Mar 16 21:00:07 volumio volumio[16540]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Mar 16 21:00:07 volumio volumio[16540]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Mar 16 21:00:07 volumio volumio[16540]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Mar 16 21:00:07 volumio volumio[16540]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Mar 16 21:00:07 volumio volumio[16540]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Mar 16 21:00:07 volumio volumio[16540]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Mar 16 21:00:07 volumio volumio[16540]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Mar 16 21:00:07 volumio volumio[16540]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Mar 16 21:00:07 volumio volumio[16540]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Mar 16 21:00:07 volumio volumio[16540]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Mar 16 21:00:07 volumio volumio[16540]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Mar 16 21:00:07 volumio volumio[16540]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Mar 16 21:00:07 volumio volumio[16540]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Mar 16 21:00:07 volumio volumio[16540]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Mar 16 21:00:07 volumio volumio[16540]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Mar 16 21:00:07 volumio volumio[16540]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 16 21:00:07 volumio volumio[16540]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Mar 16 21:00:07 volumio volumio[16540]: info: MPD Permissions set Mar 16 21:00:07 volumio volumio[16540]: info: MPD Permissions set Mar 16 21:00:07 volumio volumio[16540]: info: Upmpdcli Daemon Started Mar 16 21:00:07 volumio volumio[16540]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:07 volumio volumio[16540]: info: CoreStateMachine::pushState Mar 16 21:00:08 volumio volumio[16540]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:08 volumio volumio[16540]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:08 volumio volumio[16540]: info: Spotify config file written Mar 16 21:00:08 volumio sudo[16812]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 16 21:00:08 volumio sudo[16812]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:08 volumio volumio[16540]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:08 volumio go-librespot[16815]: Librespot-go daemon starting... Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:08 volumio sudo[16812]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio go-librespot[16815]: time="2025-03-16T21:00:08-04:00" level=info msg="generated new device id: 1a9fe321694fbbcaed04f17e681edfe3ac66cb23" Mar 16 21:00:08 volumio go-librespot[16815]: time="2025-03-16T21:00:08-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:08 volumio volumio[16540]: info: No need to fix Spotify hosts Mar 16 21:00:08 volumio go-librespot[16815]: time="2025-03-16T21:00:08-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:08 volumio volumio[16540]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:08 volumio volumio[16540]: info: CoreStateMachine::pushState Mar 16 21:00:08 volumio volumio[16540]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:08 volumio volumio[16540]: info: [squeezelite_mc] Server discovery started Mar 16 21:00:08 volumio volumio[16540]: info: [squeezelite_mc] Player finder started Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:08 volumio volumio[16540]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Mar 16 21:00:08 volumio volumio[16540]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:00:08 volumio volumio[16540]: Error: send ENETUNREACH 255.255.255.255:3483 Mar 16 21:00:08 volumio volumio[16540]: at doSend (dgram.js:692:16) Mar 16 21:00:08 volumio volumio[16540]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Mar 16 21:00:08 volumio volumio[16540]: at afterDns (dgram.js:638:5) Mar 16 21:00:08 volumio volumio[16540]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Mar 16 21:00:08 volumio volumio[16540]: errno: -101, Mar 16 21:00:08 volumio volumio[16540]: code: 'ENETUNREACH', Mar 16 21:00:08 volumio volumio[16540]: syscall: 'send', Mar 16 21:00:08 volumio volumio[16540]: address: '255.255.255.255', Mar 16 21:00:08 volumio volumio[16540]: port: 3483 Mar 16 21:00:08 volumio volumio[16540]: } Mar 16 21:00:08 volumio volumio[16540]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:00:09 volumio sudo[16842]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-16 20:59 Mar 16 21:00:09 volumio sudo[16842]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:09 volumio sudo[16842]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:09 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:09 volumio sudo[16757]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:09 volumio sudo[16731]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:09 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 16 21:00:09 volumio systemd[1]: Started dynamicswap service. Mar 16 21:00:09 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:00:09 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Mar 16 21:00:09 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 106. Mar 16 21:00:09 volumio systemd[1]: Started dynamicswap service. Mar 16 21:00:09 volumio systemd[1]: Stopped Volumio Backend Module. Mar 16 21:00:09 volumio systemd[1]: Started Volumio Backend Module. Mar 16 21:00:09 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:00:09 volumio mpd[16800]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 16 21:00:09 volumio mpd[16800]: output: No 'audio_output' defined in config file Mar 16 21:00:09 volumio mpd[16800]: output: Successfully detected a sndio audio device Mar 16 21:00:09 volumio mpd[16800]: zeroconf: No global port, disabling zeroconf Mar 16 21:00:09 volumio systemd[1]: Started Music Player Daemon. Mar 16 21:00:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 517. Mar 16 21:00:11 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:11 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:11 volumio go-librespot[16871]: Librespot-go daemon starting... Mar 16 21:00:11 volumio go-librespot[16871]: time="2025-03-16T21:00:11-04:00" level=info msg="generated new device id: bebf2f10b824d68073813a5ebb49b2f35b53ac33" Mar 16 21:00:11 volumio go-librespot[16871]: time="2025-03-16T21:00:11-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:11 volumio go-librespot[16871]: time="2025-03-16T21:00:11-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:12 volumio volumio[16856]: info: ------------------------------------------- Mar 16 21:00:12 volumio volumio[16856]: info: ----- Volumio3 ---- Mar 16 21:00:12 volumio volumio[16856]: info: ------------------------------------------- Mar 16 21:00:12 volumio volumio[16856]: info: ----- System startup ---- Mar 16 21:00:12 volumio volumio[16856]: info: ------------------------------------------- Mar 16 21:00:12 volumio volumio-remote-updater[458]: [2025-03-16 21:00:12] [connect] Successful connection Mar 16 21:00:12 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:12 volumio volumio[16856]: info: MYVOLUMIO Environment detected Mar 16 21:00:13 volumio volumio[16856]: info: Plugin folders cleanup Mar 16 21:00:13 volumio volumio[16856]: info: Scanning into folder /volumio/app/plugins/ Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category audio_interface Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category miscellanea Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category music_service Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category plugins.json Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category system_controller Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category user_interface Mar 16 21:00:13 volumio volumio[16856]: info: Scanning into folder /data/plugins/ Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category music_service Mar 16 21:00:13 volumio volumio[16856]: info: Scanning category user_interface Mar 16 21:00:13 volumio volumio[16856]: info: Plugin folders cleanup completed Mar 16 21:00:13 volumio volumio[16856]: info: ------------------------------------------- Mar 16 21:00:13 volumio volumio[16856]: info: ----- Core plugins startup ---- Mar 16 21:00:13 volumio volumio[16856]: info: ------------------------------------------- Mar 16 21:00:13 volumio volumio[16856]: info: Loading plugins from folder /volumio/app/plugins/ Mar 16 21:00:13 volumio volumio[16856]: info: Adding plugin upnp to MyMusic Plugins Mar 16 21:00:13 volumio volumio[16856]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 16 21:00:13 volumio volumio[16856]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 16 21:00:13 volumio volumio[16856]: info: Loading plugins from folder /data/plugins/ Mar 16 21:00:13 volumio volumio[16856]: info: Loading plugin "system"... Mar 16 21:00:13 volumio volumio[16856]: info: Loading plugin "appearance"... Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "network"... Mar 16 21:00:14 volumio volumio[16856]: info: Refreshing Cached IP Addresses Mar 16 21:00:14 volumio sudo[16893]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:00:14 volumio sudo[16893]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:14 volumio sudo[16895]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:00:14 volumio sudo[16895]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:14 volumio sudo[16895]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:14 volumio sudo[16893]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "services"... Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "alsa_controller"... Mar 16 21:00:14 volumio sudo[16907]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 16 21:00:14 volumio sudo[16907]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:14 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "wizard"... Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "networkfs"... Mar 16 21:00:14 volumio volumio[16856]: info: Starting Udev Watcher for removable devices Mar 16 21:00:14 volumio volumio[16856]: info: Ignoring mount for partition: boot Mar 16 21:00:14 volumio volumio[16856]: info: Ignoring mount for partition: volumio Mar 16 21:00:14 volumio volumio[16856]: info: Ignoring mount for partition: volumio_data Mar 16 21:00:14 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "volumio_command_line_client"... Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "upnp"... Mar 16 21:00:14 volumio volumio[16856]: info: [1742173214625] Starting Upmpd Daemon Mar 16 21:00:14 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "my_music"... Mar 16 21:00:14 volumio volumio[16856]: info: Loading plugin "mpd"... Mar 16 21:00:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 518. Mar 16 21:00:14 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:14 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:14 volumio go-librespot[16920]: Librespot-go daemon starting... Mar 16 21:00:14 volumio go-librespot[16920]: time="2025-03-16T21:00:14-04:00" level=info msg="generated new device id: db58083d0e6a712a079a5a7b5db512e9195c8a80" Mar 16 21:00:14 volumio go-librespot[16920]: time="2025-03-16T21:00:14-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:14 volumio go-librespot[16920]: time="2025-03-16T21:00:14-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:15 volumio sudo[16907]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "upnp_browser"... Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "alarm-clock"... Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "airplay_emulation"... Mar 16 21:00:15 volumio volumio[16856]: info: Starting Shairport Sync Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "last_100"... Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "webradio"... Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "i2s_dacs"... Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "volumiodiscovery"... Mar 16 21:00:15 volumio volumio[16856]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:15 volumio node[16856]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:15 volumio node[16856]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:15 volumio volumio[16856]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:15 volumio volumio[16856]: *** WARNING *** For more information see Mar 16 21:00:15 volumio volumio[16856]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:15 volumio volumio[16856]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:15 volumio volumio[16856]: *** WARNING *** For more information see Mar 16 21:00:15 volumio node[16856]: *** WARNING *** For more information see Mar 16 21:00:15 volumio node[16856]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:15 volumio node[16856]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:15 volumio node[16856]: *** WARNING *** For more information see Mar 16 21:00:15 volumio volumio[16856]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 16 21:00:15 volumio volumio[16856]: info: Discovery: Started advertising with name: Volumio Mar 16 21:00:15 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:15 volumio volumio[16856]: info: Loading plugin "spop"... Mar 16 21:00:17 volumio volumio[16856]: info: Loading plugin "squeezelite_mc"... Mar 16 21:00:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 519. Mar 16 21:00:18 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:18 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:18 volumio go-librespot[16930]: Librespot-go daemon starting... Mar 16 21:00:18 volumio go-librespot[16930]: time="2025-03-16T21:00:18-04:00" level=info msg="generated new device id: 21e41dce1349b2d07c1b89a4e371a99eab4b272f" Mar 16 21:00:18 volumio go-librespot[16930]: time="2025-03-16T21:00:18-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:18 volumio go-librespot[16930]: time="2025-03-16T21:00:18-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:18 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:18 volumio volumio[16856]: info: Loading plugin "youtube2"... Mar 16 21:00:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 520. Mar 16 21:00:21 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:21 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:21 volumio go-librespot[16940]: Librespot-go daemon starting... Mar 16 21:00:21 volumio go-librespot[16940]: time="2025-03-16T21:00:21-04:00" level=info msg="generated new device id: cbac7c1f9d243421cd8105294821005d777e88a2" Mar 16 21:00:21 volumio go-librespot[16940]: time="2025-03-16T21:00:21-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:21 volumio go-librespot[16940]: time="2025-03-16T21:00:21-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:22 volumio volumio[16856]: info: Loading plugin "outputs"... Mar 16 21:00:22 volumio volumio[16856]: info: Loading plugin "albumart"... Mar 16 21:00:22 volumio volumio[16856]: info: Plugin example_plugin is not enabled Mar 16 21:00:22 volumio volumio[16856]: info: Loading plugin "inputs"... Mar 16 21:00:22 volumio volumio[16856]: info: Loading plugin "updater_comm"... Mar 16 21:00:22 volumio volumio[16856]: info: Plugin mpdemulation is not enabled Mar 16 21:00:22 volumio volumio[16856]: info: Loading plugin "rest_api"... Mar 16 21:00:22 volumio volumio[16856]: info: Loading plugin "websocket"... Mar 16 21:00:22 volumio volumio[16856]: info: Starting Socket.io Server version 2.3.0 Mar 16 21:00:22 volumio volumio[16856]: info: Loading plugin "volusonic"... Mar 16 21:00:22 volumio volumio[16856]: Forking 3 albumart workers Mar 16 21:00:23 volumio volumio[16856]: info: Applying required configuration parameters for plugin volusonic Mar 16 21:00:23 volumio volumio[16856]: info: Plugin touch_display is not enabled Mar 16 21:00:23 volumio volumio[16856]: info: Loading i18n strings for locale en Mar 16 21:00:23 volumio volumio[16856]: Updating browse sources language Mar 16 21:00:23 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:23 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:24 volumio volumio[16856]: Starting albumart workers Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::initPlayerControls Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: Starting albumart workers Mar 16 21:00:24 volumio volumio[16856]: Express server listening on port 3000 Mar 16 21:00:24 volumio volumio[16856]: [Metrics] WebUI: 12s 917.45ms Mar 16 21:00:24 volumio volumio[16856]: Starting albumart workers Mar 16 21:00:24 volumio volumio[16856]: info: CoreStateMachine::resetVolumioState Mar 16 21:00:24 volumio volumio[16856]: info: CoreStateMachine::getcurrentVolume Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:24 volumio volumio[16856]: info: Volumio Network Manager: Network status updated: 0 Mar 16 21:00:24 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 521. Mar 16 21:00:24 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:24 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:24 volumio go-librespot[16984]: Librespot-go daemon starting... Mar 16 21:00:24 volumio go-librespot[16984]: time="2025-03-16T21:00:24-04:00" level=info msg="generated new device id: 2c46f46fb325cc39bca6ecfb8b5cf76725d4afa5" Mar 16 21:00:24 volumio go-librespot[16984]: time="2025-03-16T21:00:24-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:24 volumio go-librespot[16984]: time="2025-03-16T21:00:24-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:24 volumio volumio[16856]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:24 volumio sudo[17003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:00:24 volumio sudo[17003]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:24 volumio volumio[16856]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:24 volumio volumio[16856]: info: CoreStateMachine::pushState Mar 16 21:00:24 volumio sudo[17005]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:00:24 volumio sudo[17005]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:24 volumio volumio[16856]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:24 volumio volumio[16856]: info: CoreStateMachine::updateTrackBlock Mar 16 21:00:24 volumio volumio[16856]: info: CorePlayQueue::getTrackBlock Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:24 volumio sudo[17003]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:24 volumio sudo[17005]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:24 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:24 volumio volumio[16856]: info: Reloading queue from file Mar 16 21:00:25 volumio volumio[16856]: info: CoreStateMachine::setRepeat null single undefined Mar 16 21:00:25 volumio volumio[16856]: info: CoreStateMachine::pushState Mar 16 21:00:25 volumio volumio[16856]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:25 volumio volumio[16856]: info: CoreStateMachine::setRandom true Mar 16 21:00:25 volumio volumio[16856]: info: CoreStateMachine::pushState Mar 16 21:00:25 volumio volumio[16856]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:25 volumio volumio[16856]: info: Setting Device type: Raspberry PI Mar 16 21:00:25 volumio volumio[16856]: info: Completed loading Core Plugins Mar 16 21:00:25 volumio volumio[16856]: info: Preparing to generate the ALSA configuration file Mar 16 21:00:25 volumio volumio[16856]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:25 volumio volumio[16856]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 16 21:00:25 volumio volumio[16856]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 16 21:00:25 volumio volumio[16856]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 16 21:00:25 volumio volumio[16856]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 16 21:00:25 volumio volumio[16856]: info: Reading ALSA contributions from plugins. Mar 16 21:00:25 volumio volumio[16856]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:25 volumio volumio[16856]: info: CoreStateMachine::pushState Mar 16 21:00:25 volumio volumio[16856]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:25 volumio volumio[16856]: info: Asound.conf file unchanged, so no further update is needed Mar 16 21:00:25 volumio volumio[16856]: info: Output device has changed, restarting MPD Mar 16 21:00:25 volumio sudo[17041]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 16 21:00:25 volumio sudo[17041]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:25 volumio sudo[17044]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:00:25 volumio sudo[17044]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:25 volumio sudo[17044]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:25 volumio sudo[17041]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:25 volumio volumio[16856]: info: Output device has changed, restarting Shairport Sync Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:25 volumio sudo[17047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:00:25 volumio sudo[17047]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:25 volumio systemd[1]: Stopping Music Player Daemon... Mar 16 21:00:25 volumio volumio[16856]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:25 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:00:25 volumio volumio[16856]: info: ___________ START PLUGINS ___________ Mar 16 21:00:25 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:00:25 volumio volumio[16856]: info: ControllerMpd::onStart: Initializing MPD Mar 16 21:00:25 volumio volumio[16856]: info: Creating MPD Configuration file Mar 16 21:00:25 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:00:25 volumio sudo[17054]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:25 volumio sudo[17054]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:25 volumio sudo[17054]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:25 volumio volumio[16856]: info: [1742173225571] CoreMusicLibrary::Adding element Media Servers Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:25 volumio sudo[17057]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:00:25 volumio sudo[17057]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:25 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Mar 16 21:00:25 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:00:25 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:00:25 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:00:25 volumio volumio[16856]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:25 volumio volumio[16856]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:25 volumio volumio[16856]: info: [1742173225742] CoreMusicLibrary::Adding element Last_100 Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:25 volumio volumio[16856]: info: [1742173225746] CoreMusicLibrary::Adding element Webradio Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:25 volumio volumio[16856]: info: Initializing BBC Radios Mar 16 21:00:25 volumio volumio[16856]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:25 volumio sudo[17062]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 21:00:25 volumio sudo[17062]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:25 volumio sudo[17062]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:25 volumio volumio[16856]: info: Creating Spotify config file Mar 16 21:00:25 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:25 volumio ntpd[20040]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Mar 16 21:00:26 volumio volumio[16856]: info: [squeezelite_mc] Starting proxy server... Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:26 volumio volumio[16856]: info: [1742173226060] CoreMusicLibrary::Adding element YouTube2 Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:26 volumio volumio[16856]: Cannot find translation for source YouTube2 Mar 16 21:00:26 volumio volumio[16856]: info: Loading i18n strings for locale en Mar 16 21:00:26 volumio volumio[16856]: Updating browse sources language Mar 16 21:00:26 volumio volumio[16856]: Cannot find translation for source YouTube2 Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:26 volumio volumio[16856]: Cannot find translation for source YouTube2 Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:26 volumio volumio[16856]: info: [1742173226131] CoreMusicLibrary::Adding element Volusonic Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:26 volumio volumio[16856]: Cannot find translation for source YouTube2 Mar 16 21:00:26 volumio volumio[16856]: Cannot find translation for source Volusonic Mar 16 21:00:26 volumio volumio[16856]: info: Volumio Calling Home Mar 16 21:00:26 volumio volumio[16856]: info: [squeezelite_mc] Proxy server started on port 38697 Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:26 volumio volumio[16856]: Unhandled rejection Error: No sockets available, cannot start. Mar 16 21:00:26 volumio volumio[16856]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Mar 16 21:00:26 volumio volumio[16856]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Mar 16 21:00:26 volumio volumio[16856]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Mar 16 21:00:26 volumio volumio[16856]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Mar 16 21:00:26 volumio volumio[16856]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Mar 16 21:00:26 volumio volumio[16856]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Mar 16 21:00:26 volumio volumio[16856]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Mar 16 21:00:26 volumio volumio[16856]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Mar 16 21:00:26 volumio volumio[16856]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Mar 16 21:00:26 volumio volumio[16856]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Mar 16 21:00:26 volumio volumio[16856]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Mar 16 21:00:26 volumio volumio[16856]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Mar 16 21:00:26 volumio volumio[16856]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Mar 16 21:00:26 volumio volumio[16856]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Mar 16 21:00:26 volumio volumio[16856]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Mar 16 21:00:26 volumio volumio[16856]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 16 21:00:26 volumio volumio[16856]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Mar 16 21:00:26 volumio volumio[16856]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:26 volumio volumio[16856]: info: MPD Permissions set Mar 16 21:00:26 volumio volumio[16856]: info: MPD Permissions set Mar 16 21:00:26 volumio volumio[16856]: info: Upmpdcli Daemon Started Mar 16 21:00:26 volumio volumio[16856]: info: Spotify config file written Mar 16 21:00:26 volumio sudo[17084]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 16 21:00:26 volumio sudo[17084]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:26 volumio volumio[16856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio go-librespot[17086]: Librespot-go daemon starting... Mar 16 21:00:26 volumio volumio[16856]: info: No need to fix Spotify hosts Mar 16 21:00:26 volumio sudo[17084]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:26 volumio go-librespot[17086]: time="2025-03-16T21:00:26-04:00" level=info msg="generated new device id: 9c7d42128bde47ded0966beeb721a30fabc76f57" Mar 16 21:00:26 volumio go-librespot[17086]: time="2025-03-16T21:00:26-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:26 volumio go-librespot[17086]: time="2025-03-16T21:00:26-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:26 volumio volumio[16856]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:26 volumio volumio[16856]: info: CoreStateMachine::pushState Mar 16 21:00:26 volumio volumio[16856]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:26 volumio volumio[16856]: info: [squeezelite_mc] Server discovery started Mar 16 21:00:26 volumio volumio[16856]: info: [squeezelite_mc] Player finder started Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:26 volumio volumio[16856]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Mar 16 21:00:26 volumio volumio[16856]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:00:26 volumio volumio[16856]: Error: send ENETUNREACH 255.255.255.255:3483 Mar 16 21:00:26 volumio volumio[16856]: at doSend (dgram.js:692:16) Mar 16 21:00:26 volumio volumio[16856]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Mar 16 21:00:26 volumio volumio[16856]: at afterDns (dgram.js:638:5) Mar 16 21:00:26 volumio volumio[16856]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Mar 16 21:00:26 volumio volumio[16856]: errno: -101, Mar 16 21:00:26 volumio volumio[16856]: code: 'ENETUNREACH', Mar 16 21:00:26 volumio volumio[16856]: syscall: 'send', Mar 16 21:00:26 volumio volumio[16856]: address: '255.255.255.255', Mar 16 21:00:26 volumio volumio[16856]: port: 3483 Mar 16 21:00:26 volumio volumio[16856]: } Mar 16 21:00:26 volumio volumio[16856]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:00:27 volumio volumio-remote-updater[458]: [2025-03-16 21:00:27] [connect] Successful connection Mar 16 21:00:27 volumio sudo[17111]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-16 20:59 Mar 16 21:00:27 volumio sudo[17111]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:27 volumio sudo[17111]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:27 volumio mpd[17070]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 16 21:00:27 volumio mpd[17070]: output: No 'audio_output' defined in config file Mar 16 21:00:27 volumio mpd[17070]: output: Successfully detected a sndio audio device Mar 16 21:00:27 volumio mpd[17070]: zeroconf: No global port, disabling zeroconf Mar 16 21:00:27 volumio systemd[1]: Started Music Player Daemon. Mar 16 21:00:27 volumio sudo[17047]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:27 volumio sudo[17057]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:27 volumio volumio-remote-updater[458]: [2025-03-16 21:00:27] [info] asio async_read_at_least error: system:104 (Connection reset by peer) Mar 16 21:00:27 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:27 volumio volumio-remote-updater[458]: [2025-03-16 21:00:27] [error] handle_read_http_response error: websocketpp.transport:2 (Underlying Transport Error) Mar 16 21:00:27 volumio volumio-remote-updater[458]: [2025-03-16 21:00:27] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Mar 16 21:00:27 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 16 21:00:28 volumio systemd[1]: Started dynamicswap service. Mar 16 21:00:28 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:00:28 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Mar 16 21:00:28 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 107. Mar 16 21:00:28 volumio systemd[1]: Stopped Volumio Backend Module. Mar 16 21:00:28 volumio systemd[1]: Started Volumio Backend Module. Mar 16 21:00:28 volumio systemd[1]: Started dynamicswap service. Mar 16 21:00:28 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:00:28 volumio ntpd[20040]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Mar 16 21:00:29 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:29 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 522. Mar 16 21:00:29 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:29 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:29 volumio go-librespot[17139]: Librespot-go daemon starting... Mar 16 21:00:29 volumio go-librespot[17139]: time="2025-03-16T21:00:29-04:00" level=info msg="generated new device id: 98a4d7bb54e340113bc823bdcf6ae1de5989492c" Mar 16 21:00:29 volumio go-librespot[17139]: time="2025-03-16T21:00:29-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:29 volumio go-librespot[17139]: time="2025-03-16T21:00:29-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:30 volumio volumio[17126]: info: ------------------------------------------- Mar 16 21:00:30 volumio volumio[17126]: info: ----- Volumio3 ---- Mar 16 21:00:30 volumio volumio[17126]: info: ------------------------------------------- Mar 16 21:00:30 volumio volumio[17126]: info: ----- System startup ---- Mar 16 21:00:30 volumio volumio[17126]: info: ------------------------------------------- Mar 16 21:00:31 volumio volumio[17126]: info: MYVOLUMIO Environment detected Mar 16 21:00:31 volumio volumio[17126]: info: Plugin folders cleanup Mar 16 21:00:31 volumio volumio[17126]: info: Scanning into folder /volumio/app/plugins/ Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category audio_interface Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category miscellanea Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category music_service Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category plugins.json Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category system_controller Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category user_interface Mar 16 21:00:31 volumio volumio[17126]: info: Scanning into folder /data/plugins/ Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category music_service Mar 16 21:00:31 volumio volumio[17126]: info: Scanning category user_interface Mar 16 21:00:31 volumio volumio[17126]: info: Plugin folders cleanup completed Mar 16 21:00:31 volumio volumio[17126]: info: ------------------------------------------- Mar 16 21:00:31 volumio volumio[17126]: info: ----- Core plugins startup ---- Mar 16 21:00:31 volumio volumio[17126]: info: ------------------------------------------- Mar 16 21:00:31 volumio volumio[17126]: info: Loading plugins from folder /volumio/app/plugins/ Mar 16 21:00:31 volumio volumio[17126]: info: Adding plugin upnp to MyMusic Plugins Mar 16 21:00:31 volumio volumio[17126]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 16 21:00:31 volumio volumio[17126]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 16 21:00:31 volumio volumio[17126]: info: Loading plugins from folder /data/plugins/ Mar 16 21:00:31 volumio volumio[17126]: info: Loading plugin "system"... Mar 16 21:00:31 volumio volumio[17126]: info: Loading plugin "appearance"... Mar 16 21:00:32 volumio volumio[17126]: info: Loading plugin "network"... Mar 16 21:00:32 volumio volumio[17126]: info: Refreshing Cached IP Addresses Mar 16 21:00:32 volumio sudo[17163]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:00:32 volumio sudo[17163]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:32 volumio sudo[17165]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:00:32 volumio sudo[17165]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:32 volumio sudo[17165]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:32 volumio sudo[17163]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:32 volumio volumio[17126]: info: Loading plugin "services"... Mar 16 21:00:32 volumio volumio[17126]: info: Loading plugin "alsa_controller"... Mar 16 21:00:33 volumio sudo[17176]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 16 21:00:33 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:33 volumio sudo[17176]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 523. Mar 16 21:00:33 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:33 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:33 volumio volumio[17126]: info: Loading plugin "wizard"... Mar 16 21:00:33 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:33 volumio go-librespot[17183]: Librespot-go daemon starting... Mar 16 21:00:33 volumio volumio[17126]: info: Loading plugin "networkfs"... Mar 16 21:00:33 volumio go-librespot[17183]: time="2025-03-16T21:00:33-04:00" level=info msg="generated new device id: 7dda23ecfbb9f9751928784c4f394a0311c24c58" Mar 16 21:00:33 volumio go-librespot[17183]: time="2025-03-16T21:00:33-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:33 volumio go-librespot[17183]: time="2025-03-16T21:00:33-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:33 volumio volumio[17126]: info: Starting Udev Watcher for removable devices Mar 16 21:00:33 volumio volumio[17126]: info: Ignoring mount for partition: boot Mar 16 21:00:33 volumio volumio[17126]: info: Ignoring mount for partition: volumio Mar 16 21:00:33 volumio volumio[17126]: info: Ignoring mount for partition: volumio_data Mar 16 21:00:33 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:33 volumio volumio[17126]: info: Loading plugin "volumio_command_line_client"... Mar 16 21:00:33 volumio volumio[17126]: info: Loading plugin "upnp"... Mar 16 21:00:33 volumio volumio[17126]: info: [1742173233191] Starting Upmpd Daemon Mar 16 21:00:33 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:33 volumio volumio[17126]: info: Loading plugin "my_music"... Mar 16 21:00:33 volumio volumio[17126]: info: Loading plugin "mpd"... Mar 16 21:00:33 volumio sudo[17176]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:33 volumio volumio[17126]: info: Loading plugin "upnp_browser"... Mar 16 21:00:34 volumio volumio[17126]: info: Loading plugin "alarm-clock"... Mar 16 21:00:34 volumio volumio[17126]: info: Loading plugin "airplay_emulation"... Mar 16 21:00:34 volumio volumio[17126]: info: Starting Shairport Sync Mar 16 21:00:34 volumio volumio[17126]: info: Loading plugin "last_100"... Mar 16 21:00:34 volumio volumio[17126]: info: Loading plugin "webradio"... Mar 16 21:00:34 volumio volumio[17126]: info: Loading plugin "i2s_dacs"... Mar 16 21:00:34 volumio volumio[17126]: info: Loading plugin "volumiodiscovery"... Mar 16 21:00:34 volumio volumio[17126]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:34 volumio volumio[17126]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:34 volumio volumio[17126]: *** WARNING *** For more information see Mar 16 21:00:34 volumio node[17126]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:34 volumio volumio[17126]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:34 volumio volumio[17126]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:34 volumio volumio[17126]: *** WARNING *** For more information see Mar 16 21:00:34 volumio node[17126]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:34 volumio node[17126]: *** WARNING *** For more information see Mar 16 21:00:34 volumio node[17126]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:34 volumio node[17126]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:34 volumio node[17126]: *** WARNING *** For more information see Mar 16 21:00:34 volumio volumio[17126]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 16 21:00:34 volumio volumio[17126]: info: Discovery: Started advertising with name: Volumio Mar 16 21:00:34 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:34 volumio volumio[17126]: info: Loading plugin "spop"... Mar 16 21:00:35 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:36 volumio volumio[17126]: info: Loading plugin "squeezelite_mc"... Mar 16 21:00:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 524. Mar 16 21:00:36 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:36 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:36 volumio go-librespot[17199]: Librespot-go daemon starting... Mar 16 21:00:36 volumio go-librespot[17199]: time="2025-03-16T21:00:36-04:00" level=info msg="generated new device id: 7b47bc7847495e58b3bdd2c88a5f406dc95ceaf5" Mar 16 21:00:36 volumio go-librespot[17199]: time="2025-03-16T21:00:36-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:36 volumio go-librespot[17199]: time="2025-03-16T21:00:36-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:36 volumio volumio[17126]: info: Loading plugin "youtube2"... Mar 16 21:00:37 volumio volumio-remote-updater[458]: [2025-03-16 21:00:37] [connect] Successful connection Mar 16 21:00:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 525. Mar 16 21:00:39 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:39 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:39 volumio go-librespot[17206]: Librespot-go daemon starting... Mar 16 21:00:39 volumio go-librespot[17206]: time="2025-03-16T21:00:39-04:00" level=info msg="generated new device id: 3689f703d39ad53f6ed4c264c8a5e6dced5d54fb" Mar 16 21:00:39 volumio go-librespot[17206]: time="2025-03-16T21:00:39-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:39 volumio go-librespot[17206]: time="2025-03-16T21:00:39-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:40 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:40 volumio volumio[17126]: info: Loading plugin "outputs"... Mar 16 21:00:40 volumio volumio[17126]: info: Loading plugin "albumart"... Mar 16 21:00:40 volumio volumio[17126]: info: Plugin example_plugin is not enabled Mar 16 21:00:40 volumio volumio[17126]: info: Loading plugin "inputs"... Mar 16 21:00:40 volumio volumio[17126]: info: Loading plugin "updater_comm"... Mar 16 21:00:41 volumio volumio[17126]: info: Plugin mpdemulation is not enabled Mar 16 21:00:41 volumio volumio[17126]: info: Loading plugin "rest_api"... Mar 16 21:00:41 volumio volumio[17126]: info: Loading plugin "websocket"... Mar 16 21:00:41 volumio volumio[17126]: info: Starting Socket.io Server version 2.3.0 Mar 16 21:00:41 volumio volumio[17126]: info: Loading plugin "volusonic"... Mar 16 21:00:41 volumio volumio[17126]: Forking 3 albumart workers Mar 16 21:00:41 volumio ntpd[20040]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Mar 16 21:00:42 volumio volumio[17126]: info: Applying required configuration parameters for plugin volusonic Mar 16 21:00:42 volumio volumio[17126]: info: Plugin touch_display is not enabled Mar 16 21:00:42 volumio volumio[17126]: info: Loading i18n strings for locale en Mar 16 21:00:42 volumio volumio[17126]: Updating browse sources language Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::initPlayerControls Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: Starting albumart workers Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:42 volumio volumio[17126]: Express server listening on port 3000 Mar 16 21:00:42 volumio volumio[17126]: [Metrics] WebUI: 12s 796.65ms Mar 16 21:00:42 volumio volumio[17126]: Starting albumart workers Mar 16 21:00:42 volumio volumio[17126]: Starting albumart workers Mar 16 21:00:42 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:42 volumio volumio[17126]: info: CoreStateMachine::resetVolumioState Mar 16 21:00:42 volumio volumio[17126]: info: CoreStateMachine::getcurrentVolume Mar 16 21:00:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 526. Mar 16 21:00:42 volumio volumio[17126]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:42 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:42 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:42 volumio go-librespot[17247]: Librespot-go daemon starting... Mar 16 21:00:42 volumio go-librespot[17247]: time="2025-03-16T21:00:42-04:00" level=info msg="generated new device id: bd3c2473881cc333e54abecaeda2e1444eaf43fa" Mar 16 21:00:42 volumio go-librespot[17247]: time="2025-03-16T21:00:42-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:42 volumio go-librespot[17247]: time="2025-03-16T21:00:42-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:42 volumio volumio[17126]: info: Volumio Network Manager: Network status updated: 0 Mar 16 21:00:42 volumio ntpd[20040]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Mar 16 21:00:43 volumio volumio[17126]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:43 volumio sudo[17271]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:00:43 volumio sudo[17271]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:43 volumio sudo[17273]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:00:43 volumio sudo[17273]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:43 volumio sudo[17271]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:43 volumio sudo[17273]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:43 volumio volumio[17126]: info: Reloading queue from file Mar 16 21:00:43 volumio volumio[17126]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:43 volumio volumio[17126]: info: CoreStateMachine::pushState Mar 16 21:00:43 volumio volumio[17126]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:43 volumio volumio[17126]: info: CoreStateMachine::updateTrackBlock Mar 16 21:00:43 volumio volumio[17126]: info: CorePlayQueue::getTrackBlock Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:43 volumio volumio[17126]: info: CoreStateMachine::setRepeat null single undefined Mar 16 21:00:43 volumio volumio[17126]: info: CoreStateMachine::pushState Mar 16 21:00:43 volumio volumio[17126]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:43 volumio volumio[17126]: info: CoreStateMachine::setRandom true Mar 16 21:00:43 volumio volumio[17126]: info: CoreStateMachine::pushState Mar 16 21:00:43 volumio volumio[17126]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:43 volumio volumio[17126]: info: Setting Device type: Raspberry PI Mar 16 21:00:43 volumio volumio[17126]: info: Completed loading Core Plugins Mar 16 21:00:43 volumio volumio[17126]: info: Preparing to generate the ALSA configuration file Mar 16 21:00:43 volumio volumio[17126]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 16 21:00:43 volumio volumio[17126]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 16 21:00:43 volumio volumio[17126]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 16 21:00:43 volumio volumio[17126]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 16 21:00:43 volumio volumio[17126]: info: Reading ALSA contributions from plugins. Mar 16 21:00:43 volumio volumio[17126]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:43 volumio volumio[17126]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:43 volumio volumio[17126]: info: CoreStateMachine::pushState Mar 16 21:00:43 volumio volumio[17126]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:43 volumio volumio[17126]: info: Asound.conf file unchanged, so no further update is needed Mar 16 21:00:43 volumio volumio[17126]: info: Output device has changed, restarting MPD Mar 16 21:00:43 volumio sudo[17293]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 16 21:00:43 volumio sudo[17293]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:43 volumio sudo[17293]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:43 volumio volumio[17126]: info: Output device has changed, restarting Shairport Sync Mar 16 21:00:43 volumio sudo[17308]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:43 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:43 volumio sudo[17308]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:43 volumio sudo[17308]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:43 volumio sudo[17315]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:00:43 volumio sudo[17315]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:43 volumio volumio[17126]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:43 volumio volumio[17126]: info: ___________ START PLUGINS ___________ Mar 16 21:00:43 volumio systemd[1]: Stopping Music Player Daemon... Mar 16 21:00:43 volumio volumio[17126]: info: ControllerMpd::onStart: Initializing MPD Mar 16 21:00:43 volumio volumio[17126]: info: Creating MPD Configuration file Mar 16 21:00:43 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:00:43 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:00:43 volumio sudo[17322]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:00:43 volumio sudo[17322]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:44 volumio volumio[17126]: info: [1742173243994] CoreMusicLibrary::Adding element Media Servers Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:43 volumio sudo[17322]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:44 volumio sudo[17325]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:00:44 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:00:44 volumio sudo[17325]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:44 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Mar 16 21:00:44 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:00:44 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:00:44 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:00:44 volumio volumio[17126]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:44 volumio volumio[17126]: info: [1742173244169] CoreMusicLibrary::Adding element Last_100 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:44 volumio volumio[17126]: info: [1742173244173] CoreMusicLibrary::Adding element Webradio Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:44 volumio volumio[17126]: info: Initializing BBC Radios Mar 16 21:00:44 volumio sudo[17330]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 21:00:44 volumio sudo[17330]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:44 volumio volumio[17126]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:44 volumio sudo[17330]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: Creating Spotify config file Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: [squeezelite_mc] Starting proxy server... Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:44 volumio volumio[17126]: info: [1742173244501] CoreMusicLibrary::Adding element YouTube2 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:44 volumio volumio[17126]: Cannot find translation for source YouTube2 Mar 16 21:00:44 volumio volumio[17126]: info: Loading i18n strings for locale en Mar 16 21:00:44 volumio volumio[17126]: Updating browse sources language Mar 16 21:00:44 volumio volumio[17126]: Cannot find translation for source YouTube2 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:44 volumio volumio[17126]: Cannot find translation for source YouTube2 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:00:44 volumio volumio[17126]: info: [1742173244569] CoreMusicLibrary::Adding element Volusonic Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:00:44 volumio volumio[17126]: Cannot find translation for source YouTube2 Mar 16 21:00:44 volumio volumio[17126]: Cannot find translation for source Volusonic Mar 16 21:00:44 volumio volumio[17126]: info: Volumio Calling Home Mar 16 21:00:44 volumio volumio[17126]: info: [squeezelite_mc] Proxy server started on port 38349 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:00:44 volumio volumio[17126]: Unhandled rejection Error: No sockets available, cannot start. Mar 16 21:00:44 volumio volumio[17126]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Mar 16 21:00:44 volumio volumio[17126]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Mar 16 21:00:44 volumio volumio[17126]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Mar 16 21:00:44 volumio volumio[17126]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Mar 16 21:00:44 volumio volumio[17126]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Mar 16 21:00:44 volumio volumio[17126]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Mar 16 21:00:44 volumio volumio[17126]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Mar 16 21:00:44 volumio volumio[17126]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Mar 16 21:00:44 volumio volumio[17126]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Mar 16 21:00:44 volumio volumio[17126]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Mar 16 21:00:44 volumio volumio[17126]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Mar 16 21:00:44 volumio volumio[17126]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Mar 16 21:00:44 volumio volumio[17126]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Mar 16 21:00:44 volumio volumio[17126]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Mar 16 21:00:44 volumio volumio[17126]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Mar 16 21:00:44 volumio volumio[17126]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 16 21:00:44 volumio volumio[17126]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Mar 16 21:00:44 volumio volumio[17126]: info: MPD Permissions set Mar 16 21:00:44 volumio volumio[17126]: info: MPD Permissions set Mar 16 21:00:44 volumio volumio[17126]: info: Upmpdcli Daemon Started Mar 16 21:00:44 volumio volumio[17126]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:00:44 volumio volumio[17126]: info: Spotify config file written Mar 16 21:00:44 volumio sudo[17352]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 16 21:00:44 volumio sudo[17352]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:44 volumio volumio[17126]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:44 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:44 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:45 volumio go-librespot[17354]: Librespot-go daemon starting... Mar 16 21:00:45 volumio sudo[17352]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio go-librespot[17354]: time="2025-03-16T21:00:45-04:00" level=info msg="generated new device id: 3fbf7acf6672c9283f871d55ae5075e69546ce17" Mar 16 21:00:45 volumio go-librespot[17354]: time="2025-03-16T21:00:45-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:45 volumio volumio[17126]: info: No need to fix Spotify hosts Mar 16 21:00:45 volumio go-librespot[17354]: time="2025-03-16T21:00:45-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:45 volumio volumio[17126]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:00:45 volumio volumio[17126]: info: CoreStateMachine::pushState Mar 16 21:00:45 volumio volumio[17126]: info: CorePlayQueue::getTrack 0 Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::volumioPushState Mar 16 21:00:45 volumio volumio[17126]: info: [squeezelite_mc] Server discovery started Mar 16 21:00:45 volumio volumio[17126]: info: [squeezelite_mc] Player finder started Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:00:45 volumio volumio[17126]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Mar 16 21:00:45 volumio volumio[17126]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:00:45 volumio volumio[17126]: Error: send ENETUNREACH 255.255.255.255:3483 Mar 16 21:00:45 volumio volumio[17126]: at doSend (dgram.js:692:16) Mar 16 21:00:45 volumio volumio[17126]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Mar 16 21:00:45 volumio volumio[17126]: at afterDns (dgram.js:638:5) Mar 16 21:00:45 volumio volumio[17126]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Mar 16 21:00:45 volumio volumio[17126]: errno: -101, Mar 16 21:00:45 volumio volumio[17126]: code: 'ENETUNREACH', Mar 16 21:00:45 volumio volumio[17126]: syscall: 'send', Mar 16 21:00:45 volumio volumio[17126]: address: '255.255.255.255', Mar 16 21:00:45 volumio volumio[17126]: port: 3483 Mar 16 21:00:45 volumio volumio[17126]: } Mar 16 21:00:45 volumio volumio[17126]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:00:46 volumio sudo[17380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-16 20:59 Mar 16 21:00:46 volumio sudo[17380]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:46 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:46 volumio sudo[17380]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:46 volumio mpd[17338]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 16 21:00:46 volumio mpd[17338]: output: No 'audio_output' defined in config file Mar 16 21:00:46 volumio mpd[17338]: output: Successfully detected a sndio audio device Mar 16 21:00:46 volumio mpd[17338]: zeroconf: No global port, disabling zeroconf Mar 16 21:00:46 volumio systemd[1]: Started Music Player Daemon. Mar 16 21:00:46 volumio sudo[17315]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:46 volumio sudo[17325]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:46 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:46 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 16 21:00:46 volumio systemd[1]: Started dynamicswap service. Mar 16 21:00:46 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:00:46 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Mar 16 21:00:46 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 108. Mar 16 21:00:46 volumio systemd[1]: Started dynamicswap service. Mar 16 21:00:46 volumio systemd[1]: Stopped Volumio Backend Module. Mar 16 21:00:46 volumio systemd[1]: Started Volumio Backend Module. Mar 16 21:00:46 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:00:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 527. Mar 16 21:00:48 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:48 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:48 volumio go-librespot[17408]: Librespot-go daemon starting... Mar 16 21:00:48 volumio go-librespot[17408]: time="2025-03-16T21:00:48-04:00" level=info msg="generated new device id: 0e3df105a0ff5294e41da5947d5c981d47304f73" Mar 16 21:00:48 volumio go-librespot[17408]: time="2025-03-16T21:00:48-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:48 volumio go-librespot[17408]: time="2025-03-16T21:00:48-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:49 volumio volumio[17396]: info: ------------------------------------------- Mar 16 21:00:49 volumio volumio[17396]: info: ----- Volumio3 ---- Mar 16 21:00:49 volumio volumio[17396]: info: ------------------------------------------- Mar 16 21:00:49 volumio volumio[17396]: info: ----- System startup ---- Mar 16 21:00:49 volumio volumio[17396]: info: ------------------------------------------- Mar 16 21:00:50 volumio volumio[17396]: info: MYVOLUMIO Environment detected Mar 16 21:00:50 volumio volumio[17396]: info: Plugin folders cleanup Mar 16 21:00:50 volumio volumio[17396]: info: Scanning into folder /volumio/app/plugins/ Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category audio_interface Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category miscellanea Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category music_service Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category plugins.json Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category system_controller Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category user_interface Mar 16 21:00:50 volumio volumio[17396]: info: Scanning into folder /data/plugins/ Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category music_service Mar 16 21:00:50 volumio volumio[17396]: info: Scanning category user_interface Mar 16 21:00:50 volumio volumio[17396]: info: Plugin folders cleanup completed Mar 16 21:00:50 volumio volumio[17396]: info: ------------------------------------------- Mar 16 21:00:50 volumio volumio[17396]: info: ----- Core plugins startup ---- Mar 16 21:00:50 volumio volumio[17396]: info: ------------------------------------------- Mar 16 21:00:50 volumio volumio[17396]: info: Loading plugins from folder /volumio/app/plugins/ Mar 16 21:00:50 volumio volumio[17396]: info: Adding plugin upnp to MyMusic Plugins Mar 16 21:00:50 volumio volumio[17396]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 16 21:00:50 volumio volumio[17396]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 16 21:00:50 volumio volumio[17396]: info: Loading plugins from folder /data/plugins/ Mar 16 21:00:50 volumio volumio[17396]: info: Loading plugin "system"... Mar 16 21:00:50 volumio volumio[17396]: info: Loading plugin "appearance"... Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "network"... Mar 16 21:00:51 volumio volumio[17396]: info: Refreshing Cached IP Addresses Mar 16 21:00:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 528. Mar 16 21:00:51 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:51 volumio sudo[17433]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:00:51 volumio sudo[17433]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:51 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "services"... Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "alsa_controller"... Mar 16 21:00:51 volumio sudo[17436]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:00:51 volumio sudo[17436]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:51 volumio sudo[17436]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:51 volumio sudo[17433]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:51 volumio go-librespot[17434]: Librespot-go daemon starting... Mar 16 21:00:51 volumio sudo[17447]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 16 21:00:51 volumio sudo[17447]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:00:51 volumio sudo[17447]: pam_unix(sudo:session): session closed for user root Mar 16 21:00:51 volumio go-librespot[17434]: time="2025-03-16T21:00:51-04:00" level=info msg="generated new device id: 434bf692b5a6b53a0178b22765d8c6259bf77f25" Mar 16 21:00:51 volumio go-librespot[17434]: time="2025-03-16T21:00:51-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:51 volumio go-librespot[17434]: time="2025-03-16T21:00:51-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:51 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:00:51 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "wizard"... Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "networkfs"... Mar 16 21:00:51 volumio volumio[17396]: info: Starting Udev Watcher for removable devices Mar 16 21:00:51 volumio volumio[17396]: info: Ignoring mount for partition: boot Mar 16 21:00:51 volumio volumio[17396]: info: Ignoring mount for partition: volumio Mar 16 21:00:51 volumio volumio[17396]: info: Ignoring mount for partition: volumio_data Mar 16 21:00:51 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "volumio_command_line_client"... Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "upnp"... Mar 16 21:00:51 volumio volumio[17396]: info: [1742173251793] Starting Upmpd Daemon Mar 16 21:00:51 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "my_music"... Mar 16 21:00:51 volumio volumio[17396]: info: Loading plugin "mpd"... Mar 16 21:00:52 volumio volumio[17396]: info: Loading plugin "upnp_browser"... Mar 16 21:00:52 volumio volumio[17396]: info: Loading plugin "alarm-clock"... Mar 16 21:00:52 volumio volumio[17396]: info: Loading plugin "airplay_emulation"... Mar 16 21:00:52 volumio volumio[17396]: info: Starting Shairport Sync Mar 16 21:00:52 volumio volumio[17396]: info: Loading plugin "last_100"... Mar 16 21:00:52 volumio volumio[17396]: info: Loading plugin "webradio"... Mar 16 21:00:52 volumio volumio-remote-updater[458]: [2025-03-16 21:00:52] [connect] Successful connection Mar 16 21:00:53 volumio volumio[17396]: info: Loading plugin "i2s_dacs"... Mar 16 21:00:53 volumio volumio[17396]: info: Loading plugin "volumiodiscovery"... Mar 16 21:00:53 volumio volumio[17396]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:53 volumio volumio[17396]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:53 volumio node[17396]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:53 volumio volumio[17396]: *** WARNING *** For more information see Mar 16 21:00:53 volumio volumio[17396]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:53 volumio volumio[17396]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:53 volumio volumio[17396]: *** WARNING *** For more information see Mar 16 21:00:53 volumio node[17396]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:53 volumio node[17396]: *** WARNING *** For more information see Mar 16 21:00:53 volumio node[17396]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:00:53 volumio node[17396]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:00:53 volumio node[17396]: *** WARNING *** For more information see Mar 16 21:00:53 volumio volumio[17396]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 16 21:00:53 volumio volumio[17396]: info: Discovery: Started advertising with name: Volumio Mar 16 21:00:53 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:00:53 volumio volumio[17396]: info: Loading plugin "spop"... Mar 16 21:00:54 volumio volumio[17396]: info: Loading plugin "squeezelite_mc"... Mar 16 21:00:54 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 529. Mar 16 21:00:54 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:54 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:54 volumio go-librespot[17469]: Librespot-go daemon starting... Mar 16 21:00:54 volumio go-librespot[17469]: time="2025-03-16T21:00:54-04:00" level=info msg="generated new device id: 92184ffd58cf87cc1b5e723dca389d54f111bd13" Mar 16 21:00:54 volumio go-librespot[17469]: time="2025-03-16T21:00:54-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:54 volumio go-librespot[17469]: time="2025-03-16T21:00:54-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:55 volumio volumio[17396]: info: Loading plugin "youtube2"... Mar 16 21:00:57 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:00:58 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:00:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 530. Mar 16 21:00:58 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:00:58 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:00:58 volumio go-librespot[17477]: Librespot-go daemon starting... Mar 16 21:00:58 volumio go-librespot[17477]: time="2025-03-16T21:00:58-04:00" level=info msg="generated new device id: 292f753fc2ebda6ccc14dce26f006c293fcd9084" Mar 16 21:00:58 volumio go-librespot[17477]: time="2025-03-16T21:00:58-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:00:58 volumio go-librespot[17477]: time="2025-03-16T21:00:58-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:00:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:00:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:00:59 volumio volumio[17396]: info: Loading plugin "outputs"... Mar 16 21:00:59 volumio volumio[17396]: info: Loading plugin "albumart"... Mar 16 21:00:59 volumio volumio[17396]: info: Plugin example_plugin is not enabled Mar 16 21:00:59 volumio volumio[17396]: info: Loading plugin "inputs"... Mar 16 21:00:59 volumio volumio[17396]: info: Loading plugin "updater_comm"... Mar 16 21:00:59 volumio volumio[17396]: info: Plugin mpdemulation is not enabled Mar 16 21:00:59 volumio volumio[17396]: info: Loading plugin "rest_api"... Mar 16 21:00:59 volumio volumio[17396]: info: Loading plugin "websocket"... Mar 16 21:00:59 volumio volumio[17396]: info: Starting Socket.io Server version 2.3.0 Mar 16 21:00:59 volumio volumio[17396]: info: Loading plugin "volusonic"... Mar 16 21:01:00 volumio volumio[17396]: Forking 3 albumart workers Mar 16 21:01:01 volumio volumio[17396]: info: Applying required configuration parameters for plugin volusonic Mar 16 21:01:01 volumio volumio[17396]: info: Plugin touch_display is not enabled Mar 16 21:01:01 volumio volumio[17396]: info: Loading i18n strings for locale en Mar 16 21:01:01 volumio volumio[17396]: Updating browse sources language Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:01 volumio volumio[17396]: Starting albumart workers Mar 16 21:01:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:01:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 531. Mar 16 21:01:01 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:01 volumio volumio[17396]: Starting albumart workers Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::initPlayerControls Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:01 volumio volumio[17396]: Starting albumart workers Mar 16 21:01:01 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:01 volumio volumio[17396]: Express server listening on port 3000 Mar 16 21:01:01 volumio volumio[17396]: [Metrics] WebUI: 12s 899.99ms Mar 16 21:01:01 volumio go-librespot[17516]: Librespot-go daemon starting... Mar 16 21:01:01 volumio go-librespot[17516]: time="2025-03-16T21:01:01-04:00" level=info msg="generated new device id: 85a868e0febe849f1db26d109ebc857b3d4d1773" Mar 16 21:01:01 volumio go-librespot[17516]: time="2025-03-16T21:01:01-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:01 volumio go-librespot[17516]: time="2025-03-16T21:01:01-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:01 volumio volumio[17396]: info: CoreStateMachine::resetVolumioState Mar 16 21:01:01 volumio volumio[17396]: info: CoreStateMachine::getcurrentVolume Mar 16 21:01:01 volumio volumio[17396]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:01:01 volumio volumio[17396]: info: Volumio Network Manager: Network status updated: 0 Mar 16 21:01:01 volumio volumio[17396]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Mar 16 21:01:01 volumio volumio[17396]: wlan0 Interface doesn't support scanning : Device or resource busy Mar 16 21:01:01 volumio volumio[17396]: info: Cannot use regular scanning, forcing with ap-force Mar 16 21:01:01 volumio sudo[17537]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Mar 16 21:01:01 volumio sudo[17537]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:02 volumio sudo[17537]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:02 volumio sudo[17570]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:01:02 volumio sudo[17570]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:02 volumio sudo[17573]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:01:02 volumio sudo[17570]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:02 volumio sudo[17573]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:02 volumio sudo[17573]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:02 volumio volumio[17396]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:02 volumio volumio[17396]: info: Reloading queue from file Mar 16 21:01:02 volumio volumio[17396]: info: CoreStateMachine::setRepeat null single undefined Mar 16 21:01:02 volumio volumio[17396]: info: CoreStateMachine::pushState Mar 16 21:01:02 volumio volumio[17396]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:02 volumio volumio[17396]: info: CoreStateMachine::setRandom true Mar 16 21:01:02 volumio volumio[17396]: info: CoreStateMachine::pushState Mar 16 21:01:02 volumio volumio[17396]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:02 volumio volumio[17396]: info: Setting Device type: Raspberry PI Mar 16 21:01:02 volumio volumio[17396]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 16 21:01:02 volumio volumio[17396]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 16 21:01:02 volumio volumio[17396]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 16 21:01:02 volumio volumio[17396]: info: Completed loading Core Plugins Mar 16 21:01:02 volumio volumio[17396]: info: Preparing to generate the ALSA configuration file Mar 16 21:01:02 volumio volumio[17396]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:01:02 volumio volumio[17396]: info: CoreStateMachine::pushState Mar 16 21:01:02 volumio volumio[17396]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:02 volumio volumio[17396]: info: CoreStateMachine::updateTrackBlock Mar 16 21:01:02 volumio volumio[17396]: info: CorePlayQueue::getTrackBlock Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:01:02 volumio volumio[17396]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 16 21:01:02 volumio volumio[17396]: info: Reading ALSA contributions from plugins. Mar 16 21:01:02 volumio volumio[17396]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:01:02 volumio sudo[17584]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 16 21:01:02 volumio sudo[17584]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:02 volumio sudo[17584]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:02 volumio volumio[17396]: info: Upmpdcli Daemon Started Mar 16 21:01:02 volumio volumio[17396]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:01:02 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:01:02 volumio volumio[17396]: info: CoreStateMachine::pushState Mar 16 21:01:02 volumio volumio[17396]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:02 volumio volumio[17396]: info: Asound.conf file unchanged, so no further update is needed Mar 16 21:01:02 volumio volumio[17396]: info: Output device has changed, restarting MPD Mar 16 21:01:02 volumio sudo[17588]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:01:02 volumio sudo[17588]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:02 volumio sudo[17588]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:02 volumio volumio[17396]: info: Output device has changed, restarting Shairport Sync Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:02 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:02 volumio sudo[17591]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:01:02 volumio sudo[17591]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:02 volumio systemd[1]: Stopping Music Player Daemon... Mar 16 21:01:02 volumio volumio[17396]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:01:02 volumio volumio[17396]: info: ___________ START PLUGINS ___________ Mar 16 21:01:02 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:01:02 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:01:03 volumio volumio[17396]: info: ControllerMpd::onStart: Initializing MPD Mar 16 21:01:03 volumio volumio[17396]: info: Creating MPD Configuration file Mar 16 21:01:03 volumio sudo[17598]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:01:03 volumio sudo[17598]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:03 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:01:03 volumio sudo[17598]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:03 volumio volumio[17396]: info: [1742173263123] CoreMusicLibrary::Adding element Media Servers Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:03 volumio sudo[17601]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:01:03 volumio sudo[17601]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:03 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Mar 16 21:01:03 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:01:03 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:01:03 volumio volumio[17396]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:03 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:01:03 volumio volumio[17396]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:03 volumio volumio[17396]: info: [1742173263304] CoreMusicLibrary::Adding element Last_100 Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:03 volumio volumio[17396]: info: [1742173263308] CoreMusicLibrary::Adding element Webradio Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:01:03 volumio volumio[17396]: info: Initializing BBC Radios Mar 16 21:01:03 volumio volumio[17396]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:03 volumio sudo[17606]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:01:03 volumio sudo[17606]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:03 volumio sudo[17606]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:03 volumio volumio[17396]: info: Creating Spotify config file Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:03 volumio volumio[17396]: info: [squeezelite_mc] Starting proxy server... Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:03 volumio volumio[17396]: info: [1742173263621] CoreMusicLibrary::Adding element YouTube2 Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:03 volumio volumio[17396]: Cannot find translation for source YouTube2 Mar 16 21:01:03 volumio volumio[17396]: info: Loading i18n strings for locale en Mar 16 21:01:03 volumio volumio[17396]: Updating browse sources language Mar 16 21:01:03 volumio volumio[17396]: Cannot find translation for source YouTube2 Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:03 volumio volumio[17396]: Cannot find translation for source YouTube2 Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:03 volumio volumio[17396]: info: [1742173263696] CoreMusicLibrary::Adding element Volusonic Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:03 volumio volumio[17396]: Cannot find translation for source YouTube2 Mar 16 21:01:03 volumio volumio[17396]: Cannot find translation for source Volusonic Mar 16 21:01:03 volumio volumio[17396]: info: Volumio Calling Home Mar 16 21:01:03 volumio volumio[17396]: info: [squeezelite_mc] Proxy server started on port 41219 Mar 16 21:01:03 volumio volumio[17396]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:01:03 volumio volumio[17396]: Unhandled rejection Error: No sockets available, cannot start. Mar 16 21:01:03 volumio volumio[17396]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Mar 16 21:01:03 volumio volumio[17396]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Mar 16 21:01:03 volumio volumio[17396]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Mar 16 21:01:03 volumio volumio[17396]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Mar 16 21:01:03 volumio volumio[17396]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Mar 16 21:01:03 volumio volumio[17396]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Mar 16 21:01:03 volumio volumio[17396]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Mar 16 21:01:03 volumio volumio[17396]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Mar 16 21:01:03 volumio volumio[17396]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Mar 16 21:01:03 volumio volumio[17396]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Mar 16 21:01:03 volumio volumio[17396]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Mar 16 21:01:03 volumio volumio[17396]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Mar 16 21:01:03 volumio volumio[17396]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Mar 16 21:01:03 volumio volumio[17396]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Mar 16 21:01:03 volumio volumio[17396]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Mar 16 21:01:03 volumio volumio[17396]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 16 21:01:03 volumio volumio[17396]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Mar 16 21:01:03 volumio volumio[17396]: info: MPD Permissions set Mar 16 21:01:03 volumio volumio[17396]: info: MPD Permissions set Mar 16 21:01:03 volumio volumio[17396]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:01:04 volumio volumio[17396]: info: Spotify config file written Mar 16 21:01:04 volumio sudo[17628]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 16 21:01:04 volumio sudo[17628]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:04 volumio volumio[17396]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:04 volumio go-librespot[17630]: Librespot-go daemon starting... Mar 16 21:01:04 volumio sudo[17628]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:04 volumio go-librespot[17630]: time="2025-03-16T21:01:04-04:00" level=info msg="generated new device id: c2faa4720d87d9cfac7982ff6b9fbe7fa7f6df2c" Mar 16 21:01:04 volumio go-librespot[17630]: time="2025-03-16T21:01:04-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: No need to fix Spotify hosts Mar 16 21:01:04 volumio go-librespot[17630]: time="2025-03-16T21:01:04-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:04 volumio volumio[17396]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:01:04 volumio volumio[17396]: info: CoreStateMachine::pushState Mar 16 21:01:04 volumio volumio[17396]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:04 volumio volumio[17396]: info: [squeezelite_mc] Server discovery started Mar 16 21:01:04 volumio volumio[17396]: info: [squeezelite_mc] Player finder started Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:04 volumio volumio[17396]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Mar 16 21:01:04 volumio volumio[17396]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:01:04 volumio volumio[17396]: Error: send ENETUNREACH 255.255.255.255:3483 Mar 16 21:01:04 volumio volumio[17396]: at doSend (dgram.js:692:16) Mar 16 21:01:04 volumio volumio[17396]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Mar 16 21:01:04 volumio volumio[17396]: at afterDns (dgram.js:638:5) Mar 16 21:01:04 volumio volumio[17396]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Mar 16 21:01:04 volumio volumio[17396]: errno: -101, Mar 16 21:01:04 volumio volumio[17396]: code: 'ENETUNREACH', Mar 16 21:01:04 volumio volumio[17396]: syscall: 'send', Mar 16 21:01:04 volumio volumio[17396]: address: '255.255.255.255', Mar 16 21:01:04 volumio volumio[17396]: port: 3483 Mar 16 21:01:04 volumio volumio[17396]: } Mar 16 21:01:04 volumio volumio[17396]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:01:05 volumio sudo[17656]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-16 21:00 Mar 16 21:01:05 volumio sudo[17656]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:05 volumio sudo[17656]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:05 volumio mpd[17621]: decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 16 21:01:05 volumio mpd[17621]: output: No 'audio_output' defined in config file Mar 16 21:01:05 volumio mpd[17621]: output: Successfully detected a sndio audio device Mar 16 21:01:05 volumio mpd[17621]: zeroconf: No global port, disabling zeroconf Mar 16 21:01:05 volumio systemd[1]: Started Music Player Daemon. Mar 16 21:01:05 volumio sudo[17601]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:05 volumio sudo[17591]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:05 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:05 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 16 21:01:05 volumio systemd[1]: Started dynamicswap service. Mar 16 21:01:05 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:01:05 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Mar 16 21:01:05 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 109. Mar 16 21:01:05 volumio systemd[1]: Started dynamicswap service. Mar 16 21:01:05 volumio systemd[1]: Stopped Volumio Backend Module. Mar 16 21:01:05 volumio systemd[1]: Started Volumio Backend Module. Mar 16 21:01:05 volumio systemd[1]: dynamicswap.service: Succeeded. Mar 16 21:01:07 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:01:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 532. Mar 16 21:01:07 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:07 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:07 volumio go-librespot[17684]: Librespot-go daemon starting... Mar 16 21:01:07 volumio go-librespot[17684]: time="2025-03-16T21:01:07-04:00" level=info msg="generated new device id: 1d0e9a6ed227756fb4751357d13ce2c82ef2dc43" Mar 16 21:01:07 volumio go-librespot[17684]: time="2025-03-16T21:01:07-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:07 volumio go-librespot[17684]: time="2025-03-16T21:01:07-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:07 volumio volumio-remote-updater[458]: [2025-03-16 21:01:07] [connect] Successful connection Mar 16 21:01:07 volumio volumio[17672]: info: ------------------------------------------- Mar 16 21:01:07 volumio volumio[17672]: info: ----- Volumio3 ---- Mar 16 21:01:07 volumio volumio[17672]: info: ------------------------------------------- Mar 16 21:01:07 volumio volumio[17672]: info: ----- System startup ---- Mar 16 21:01:07 volumio volumio[17672]: info: ------------------------------------------- Mar 16 21:01:08 volumio wpa_supplicant[754]: wlan0: Failed to initiate sched scan Mar 16 21:01:08 volumio volumio[17672]: info: MYVOLUMIO Environment detected Mar 16 21:01:08 volumio volumio[17672]: info: Plugin folders cleanup Mar 16 21:01:08 volumio volumio[17672]: info: Scanning into folder /volumio/app/plugins/ Mar 16 21:01:08 volumio volumio[17672]: info: Scanning category audio_interface Mar 16 21:01:08 volumio volumio[17672]: info: Scanning category miscellanea Mar 16 21:01:08 volumio volumio[17672]: info: Scanning category music_service Mar 16 21:01:08 volumio volumio[17672]: info: Scanning category plugins.json Mar 16 21:01:08 volumio volumio[17672]: info: Scanning category system_controller Mar 16 21:01:08 volumio volumio[17672]: info: Scanning category user_interface Mar 16 21:01:08 volumio volumio[17672]: info: Scanning into folder /data/plugins/ Mar 16 21:01:08 volumio volumio[17672]: info: Scanning category music_service Mar 16 21:01:09 volumio volumio[17672]: info: Scanning category user_interface Mar 16 21:01:09 volumio volumio[17672]: info: Plugin folders cleanup completed Mar 16 21:01:09 volumio volumio[17672]: info: ------------------------------------------- Mar 16 21:01:09 volumio volumio[17672]: info: ----- Core plugins startup ---- Mar 16 21:01:09 volumio volumio[17672]: info: ------------------------------------------- Mar 16 21:01:09 volumio volumio[17672]: info: Loading plugins from folder /volumio/app/plugins/ Mar 16 21:01:09 volumio volumio[17672]: info: Adding plugin upnp to MyMusic Plugins Mar 16 21:01:09 volumio volumio[17672]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 16 21:01:09 volumio volumio[17672]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 16 21:01:09 volumio volumio[17672]: info: Loading plugins from folder /data/plugins/ Mar 16 21:01:09 volumio volumio[17672]: info: Loading plugin "system"... Mar 16 21:01:09 volumio volumio[17672]: info: Loading plugin "appearance"... Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "network"... Mar 16 21:01:10 volumio volumio[17672]: info: Refreshing Cached IP Addresses Mar 16 21:01:10 volumio sudo[17749]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:01:10 volumio sudo[17749]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:10 volumio sudo[17751]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:01:10 volumio sudo[17751]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:10 volumio sudo[17749]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:10 volumio sudo[17751]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "services"... Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "alsa_controller"... Mar 16 21:01:10 volumio sudo[17762]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 16 21:01:10 volumio sudo[17762]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:01:10 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:01:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 533. Mar 16 21:01:10 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "wizard"... Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "networkfs"... Mar 16 21:01:10 volumio volumio[17672]: info: Starting Udev Watcher for removable devices Mar 16 21:01:10 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:10 volumio go-librespot[17776]: Librespot-go daemon starting... Mar 16 21:01:10 volumio volumio[17672]: info: Ignoring mount for partition: boot Mar 16 21:01:10 volumio volumio[17672]: info: Ignoring mount for partition: volumio Mar 16 21:01:10 volumio volumio[17672]: info: Ignoring mount for partition: volumio_data Mar 16 21:01:10 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "volumio_command_line_client"... Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "upnp"... Mar 16 21:01:10 volumio volumio[17672]: info: [1742173270618] Starting Upmpd Daemon Mar 16 21:01:10 volumio go-librespot[17776]: time="2025-03-16T21:01:10-04:00" level=info msg="generated new device id: c962fe21c638fd816106f341e3fde943a3fdbbdc" Mar 16 21:01:10 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:01:10 volumio go-librespot[17776]: time="2025-03-16T21:01:10-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "my_music"... Mar 16 21:01:10 volumio go-librespot[17776]: time="2025-03-16T21:01:10-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:10 volumio volumio[17672]: info: Loading plugin "mpd"... Mar 16 21:01:11 volumio sudo[17762]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "upnp_browser"... Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "alarm-clock"... Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "airplay_emulation"... Mar 16 21:01:11 volumio volumio[17672]: info: Starting Shairport Sync Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "last_100"... Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "webradio"... Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "i2s_dacs"... Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "volumiodiscovery"... Mar 16 21:01:11 volumio volumio[17672]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:01:11 volumio volumio[17672]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:01:11 volumio volumio[17672]: *** WARNING *** For more information see Mar 16 21:01:11 volumio node[17672]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 16 21:01:11 volumio volumio[17672]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:01:11 volumio volumio[17672]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:01:11 volumio volumio[17672]: *** WARNING *** For more information see Mar 16 21:01:11 volumio node[17672]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:01:11 volumio node[17672]: *** WARNING *** For more information see Mar 16 21:01:11 volumio node[17672]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 16 21:01:11 volumio node[17672]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 16 21:01:11 volumio node[17672]: *** WARNING *** For more information see Mar 16 21:01:11 volumio volumio[17672]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 16 21:01:11 volumio volumio[17672]: info: Discovery: Started advertising with name: Volumio Mar 16 21:01:11 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 16 21:01:11 volumio volumio[17672]: info: Loading plugin "spop"... Mar 16 21:01:13 volumio volumio[17672]: info: Loading plugin "squeezelite_mc"... Mar 16 21:01:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:01:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 534. Mar 16 21:01:13 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:13 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:13 volumio go-librespot[17785]: Librespot-go daemon starting... Mar 16 21:01:13 volumio go-librespot[17785]: time="2025-03-16T21:01:13-04:00" level=info msg="generated new device id: 590babed0034d4b0f96915f99ba8276896e92dbc" Mar 16 21:01:13 volumio go-librespot[17785]: time="2025-03-16T21:01:13-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:13 volumio go-librespot[17785]: time="2025-03-16T21:01:13-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:13 volumio wpa_supplicant[754]: wlan0: Trying to associate with SSID 'Gilliland' Mar 16 21:01:14 volumio wpa_supplicant[754]: wlan0: Associated with a8:6e:84:de:aa:6c Mar 16 21:01:14 volumio wpa_supplicant[754]: wlan0: CTRL-EVENT-CONNECTED - Connection to a8:6e:84:de:aa:6c completed [id=0 id_str=] Mar 16 21:01:14 volumio wpa_supplicant[754]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 16 21:01:14 volumio wpa_supplicant[754]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: carrier acquired Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: IAID 67:9a:d4:d9 Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: carrier lost Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: carrier acquired Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: IAID 67:9a:d4:d9 Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: soliciting an IPv6 router Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: rebinding lease of 192.168.19.64 Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: NAK: wrong network from 192.168.0.1 Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: message: wrong network Mar 16 21:01:14 volumio dhcpcd[774]: wlan0: soliciting a DHCP lease Mar 16 21:01:14 volumio volumio[17672]: info: Loading plugin "youtube2"... Mar 16 21:01:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:01:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 535. Mar 16 21:01:17 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:17 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:17 volumio go-librespot[17816]: Librespot-go daemon starting... Mar 16 21:01:17 volumio go-librespot[17816]: time="2025-03-16T21:01:17-04:00" level=info msg="generated new device id: 0f39c90065b1a8ba7d8831b27e2231063330cf0f" Mar 16 21:01:17 volumio go-librespot[17816]: time="2025-03-16T21:01:17-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:17 volumio go-librespot[17816]: time="2025-03-16T21:01:17-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:17 volumio dhcpcd[774]: wlan0: offered 192.168.0.209 from 192.168.0.1 Mar 16 21:01:17 volumio dhcpcd[774]: wlan0: probing address 192.168.0.209/24 Mar 16 21:01:18 volumio volumio[17672]: info: Loading plugin "outputs"... Mar 16 21:01:18 volumio volumio[17672]: info: Loading plugin "albumart"... Mar 16 21:01:18 volumio volumio[17672]: info: Plugin example_plugin is not enabled Mar 16 21:01:18 volumio volumio[17672]: info: Loading plugin "inputs"... Mar 16 21:01:18 volumio volumio[17672]: info: Loading plugin "updater_comm"... Mar 16 21:01:18 volumio volumio[17672]: info: Plugin mpdemulation is not enabled Mar 16 21:01:18 volumio volumio[17672]: info: Loading plugin "rest_api"... Mar 16 21:01:18 volumio volumio[17672]: info: Loading plugin "websocket"... Mar 16 21:01:18 volumio volumio[17672]: info: Starting Socket.io Server version 2.3.0 Mar 16 21:01:18 volumio volumio[17672]: info: Loading plugin "volusonic"... Mar 16 21:01:19 volumio volumio[17672]: Forking 3 albumart workers Mar 16 21:01:19 volumio volumio[17672]: info: Applying required configuration parameters for plugin volusonic Mar 16 21:01:19 volumio volumio[17672]: info: Plugin touch_display is not enabled Mar 16 21:01:19 volumio volumio[17672]: info: Loading i18n strings for locale en Mar 16 21:01:20 volumio volumio[17672]: Updating browse sources language Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:20 volumio volumio[17672]: Starting albumart workers Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: Starting albumart workers Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::initPlayerControls Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:20 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 16 21:01:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 536. Mar 16 21:01:20 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:20 volumio volumio[17672]: Express server listening on port 3000 Mar 16 21:01:20 volumio volumio[17672]: Starting albumart workers Mar 16 21:01:20 volumio volumio[17672]: [Metrics] WebUI: 13s 62.63ms Mar 16 21:01:20 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:20 volumio go-librespot[17855]: Librespot-go daemon starting... Mar 16 21:01:20 volumio volumio[17672]: info: CoreStateMachine::resetVolumioState Mar 16 21:01:20 volumio volumio[17672]: info: CoreStateMachine::getcurrentVolume Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:01:20 volumio go-librespot[17855]: time="2025-03-16T21:01:20-04:00" level=info msg="generated new device id: 7d9ea77e0fefc36ca098b884cdc85a05d9d24cc0" Mar 16 21:01:20 volumio go-librespot[17855]: time="2025-03-16T21:01:20-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:20 volumio go-librespot[17855]: time="2025-03-16T21:01:20-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:20 volumio volumio[17672]: info: Volumio Network Manager: Network status updated: 0 Mar 16 21:01:20 volumio volumio[17672]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:01:20 volumio sudo[17882]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 16 21:01:20 volumio sudo[17882]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:20 volumio sudo[17882]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:20 volumio sudo[17886]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 16 21:01:20 volumio sudo[17886]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:20 volumio volumio[17672]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:01:20 volumio volumio[17672]: info: CoreStateMachine::pushState Mar 16 21:01:20 volumio volumio[17672]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:20 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:21 volumio sudo[17886]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:21 volumio volumio[17672]: info: CoreStateMachine::updateTrackBlock Mar 16 21:01:21 volumio volumio[17672]: info: CorePlayQueue::getTrackBlock Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: Reloading queue from file Mar 16 21:01:21 volumio volumio[17672]: info: CoreStateMachine::setRepeat null single undefined Mar 16 21:01:21 volumio volumio[17672]: info: CoreStateMachine::pushState Mar 16 21:01:21 volumio volumio[17672]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:21 volumio volumio[17672]: info: CoreStateMachine::setRandom true Mar 16 21:01:21 volumio volumio[17672]: info: CoreStateMachine::pushState Mar 16 21:01:21 volumio volumio[17672]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:21 volumio volumio[17672]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 16 21:01:21 volumio volumio[17672]: info: USB Boot Capable - System SBC Revision found in cpuinfo: 902120 Mar 16 21:01:21 volumio volumio[17672]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 16 21:01:21 volumio volumio[17672]: info: Setting Device type: Raspberry PI Mar 16 21:01:21 volumio volumio[17672]: info: Completed loading Core Plugins Mar 16 21:01:21 volumio volumio[17672]: info: Preparing to generate the ALSA configuration file Mar 16 21:01:21 volumio volumio[17672]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:01:21 volumio volumio[17672]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Mar 16 21:01:21 volumio volumio[17672]: info: Reading ALSA contributions from plugins. Mar 16 21:01:21 volumio volumio[17672]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:01:21 volumio volumio[17672]: info: CoreStateMachine::pushState Mar 16 21:01:21 volumio volumio[17672]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:21 volumio volumio[17672]: info: Asound.conf file unchanged, so no further update is needed Mar 16 21:01:21 volumio volumio[17672]: info: Output device has changed, restarting MPD Mar 16 21:01:21 volumio sudo[17913]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 16 21:01:21 volumio sudo[17913]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:21 volumio sudo[17913]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:21 volumio sudo[17923]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:01:21 volumio sudo[17923]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:21 volumio sudo[17923]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:21 volumio volumio[17672]: info: Output device has changed, restarting Shairport Sync Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:21 volumio sudo[17926]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:01:21 volumio sudo[17926]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:21 volumio systemd[1]: Stopping Music Player Daemon... Mar 16 21:01:21 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:01:21 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:01:21 volumio volumio[17672]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:01:21 volumio volumio[17672]: info: ___________ START PLUGINS ___________ Mar 16 21:01:21 volumio volumio[17672]: info: ControllerMpd::onStart: Initializing MPD Mar 16 21:01:21 volumio volumio[17672]: info: Creating MPD Configuration file Mar 16 21:01:21 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:01:21 volumio sudo[17933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 16 21:01:21 volumio sudo[17933]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:21 volumio sudo[17933]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:21 volumio volumio[17672]: info: [1742173281618] CoreMusicLibrary::Adding element Media Servers Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:21 volumio sudo[17935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 16 21:01:21 volumio sudo[17935]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:21 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Mar 16 21:01:21 volumio systemd[1]: mpd.service: Succeeded. Mar 16 21:01:21 volumio systemd[1]: Stopped Music Player Daemon. Mar 16 21:01:21 volumio systemd[1]: Starting Music Player Daemon... Mar 16 21:01:21 volumio volumio[17672]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:21 volumio volumio[17672]: info: [1742173281798] CoreMusicLibrary::Adding element Last_100 Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:21 volumio volumio[17672]: info: [1742173281802] CoreMusicLibrary::Adding element Webradio Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:01:21 volumio volumio[17672]: info: Initializing BBC Radios Mar 16 21:01:21 volumio sudo[17941]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 16 21:01:21 volumio sudo[17941]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:21 volumio sudo[17941]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:21 volumio volumio[17672]: /usr/bin/md5sum: /sys/class/net/eth0/address: No such file or directory Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:21 volumio volumio[17672]: info: Creating Spotify config file Mar 16 21:01:21 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: [squeezelite_mc] Starting proxy server... Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:22 volumio volumio[17672]: info: [1742173282129] CoreMusicLibrary::Adding element YouTube2 Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:22 volumio volumio[17672]: Cannot find translation for source YouTube2 Mar 16 21:01:22 volumio volumio[17672]: info: Loading i18n strings for locale en Mar 16 21:01:22 volumio volumio[17672]: Updating browse sources language Mar 16 21:01:22 volumio volumio[17672]: Cannot find translation for source YouTube2 Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:22 volumio volumio[17672]: Cannot find translation for source YouTube2 Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 16 21:01:22 volumio volumio[17672]: info: [1742173282199] CoreMusicLibrary::Adding element Volusonic Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 16 21:01:22 volumio volumio[17672]: Cannot find translation for source YouTube2 Mar 16 21:01:22 volumio volumio[17672]: Cannot find translation for source Volusonic Mar 16 21:01:22 volumio volumio[17672]: info: Volumio Calling Home Mar 16 21:01:22 volumio volumio[17672]: info: [squeezelite_mc] Proxy server started on port 45343 Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::volumioRetrievevolume Mar 16 21:01:22 volumio volumio[17672]: Unhandled rejection Error: No sockets available, cannot start. Mar 16 21:01:22 volumio volumio[17672]: at SsdpClient.SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Mar 16 21:01:22 volumio volumio[17672]: at SsdpClient.SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Mar 16 21:01:22 volumio volumio[17672]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Mar 16 21:01:22 volumio volumio[17672]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Mar 16 21:01:22 volumio volumio[17672]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Mar 16 21:01:22 volumio volumio[17672]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Mar 16 21:01:22 volumio volumio[17672]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Mar 16 21:01:22 volumio volumio[17672]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Mar 16 21:01:22 volumio volumio[17672]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:126:12) Mar 16 21:01:22 volumio volumio[17672]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Mar 16 21:01:22 volumio volumio[17672]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Mar 16 21:01:22 volumio volumio[17672]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Mar 16 21:01:22 volumio volumio[17672]: at HashMap.proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Mar 16 21:01:22 volumio volumio[17672]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Mar 16 21:01:22 volumio volumio[17672]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Mar 16 21:01:22 volumio volumio[17672]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 16 21:01:22 volumio volumio[17672]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Mar 16 21:01:22 volumio volumio[17672]: info: MPD Permissions set Mar 16 21:01:22 volumio volumio[17672]: info: MPD Permissions set Mar 16 21:01:22 volumio volumio[17672]: info: Upmpdcli Daemon Started Mar 16 21:01:22 volumio volumio[17672]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control '',0 Mar 16 21:01:22 volumio volumio[17672]: info: Spotify config file written Mar 16 21:01:22 volumio sudo[17963]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 16 21:01:22 volumio sudo[17963]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:22 volumio volumio[17672]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio systemd[1]: Stopped go-librespot Daemon. Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio systemd[1]: Started go-librespot Daemon. Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 16 21:01:22 volumio go-librespot[17966]: Librespot-go daemon starting... Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: No need to fix Spotify hosts Mar 16 21:01:22 volumio sudo[17963]: pam_unix(sudo:session): session closed for user root Mar 16 21:01:22 volumio go-librespot[17966]: time="2025-03-16T21:01:22-04:00" level=info msg="generated new device id: 93410571b2e03e9b709673c59e2e80ec647c3fc8" Mar 16 21:01:22 volumio go-librespot[17966]: time="2025-03-16T21:01:22-04:00" level=debug msg="stored credentials found for 1245837727" Mar 16 21:01:22 volumio go-librespot[17966]: time="2025-03-16T21:01:22-04:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Mar 16 21:01:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 16 21:01:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 16 21:01:22 volumio volumio[17672]: info: VolumeController:: Volume=undefined Mute =false Mar 16 21:01:22 volumio volumio[17672]: info: CoreStateMachine::pushState Mar 16 21:01:22 volumio volumio[17672]: info: CorePlayQueue::getTrack 0 Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::volumioPushState Mar 16 21:01:22 volumio volumio[17672]: info: [squeezelite_mc] Server discovery started Mar 16 21:01:22 volumio volumio[17672]: info: [squeezelite_mc] Player finder started Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 16 21:01:22 volumio volumio[17672]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Mar 16 21:01:22 volumio volumio[17672]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:01:22 volumio volumio[17672]: Error: send ENETUNREACH 255.255.255.255:3483 Mar 16 21:01:22 volumio volumio[17672]: at doSend (dgram.js:692:16) Mar 16 21:01:22 volumio volumio[17672]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Mar 16 21:01:22 volumio volumio[17672]: at afterDns (dgram.js:638:5) Mar 16 21:01:22 volumio volumio[17672]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Mar 16 21:01:22 volumio volumio[17672]: errno: -101, Mar 16 21:01:22 volumio volumio[17672]: code: 'ENETUNREACH', Mar 16 21:01:22 volumio volumio[17672]: syscall: 'send', Mar 16 21:01:22 volumio volumio[17672]: address: '255.255.255.255', Mar 16 21:01:22 volumio volumio[17672]: port: 3483 Mar 16 21:01:22 volumio volumio[17672]: } Mar 16 21:01:22 volumio volumio[17672]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 16 21:01:22 volumio volumio-remote-updater[458]: [2025-03-16 21:01:22] [connect] Successful connection Mar 16 21:01:23 volumio dhcpcd[774]: wlan0: leased 192.168.0.209 for 7200 seconds Mar 16 21:01:23 volumio dhcpcd[774]: wlan0: adding route to 192.168.0.0/24 Mar 16 21:01:23 volumio dhcpcd[774]: wlan0: adding default route via 192.168.0.1 Mar 16 21:01:23 volumio avahi-daemon[454]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.209. Mar 16 21:01:23 volumio avahi-daemon[454]: New relevant interface wlan0.IPv4 for mDNS. Mar 16 21:01:23 volumio avahi-daemon[454]: Registering new address record for 192.168.0.209 on wlan0.IPv4. Mar 16 21:01:23 volumio sudo[18002]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-16 21:00 Mar 16 21:01:23 volumio sudo[18002]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 16 21:01:23 volumio systemd[1]: Stopping Network Time Service... 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"