Jul 03 09:37:07 volumio ntpd[1003]: DNS: dns_check: processing 3.debian.pool.ntp.org, 8, 101 Jul 03 09:37:07 volumio ntpd[1003]: DNS: dns_check: DNS error: -11, System error Jul 03 09:37:07 volumio ntpd[1003]: DNS: dns_take_status: 3.debian.pool.ntp.org=>error, 12 Jul 03 09:37:08 volumio ntpd[1003]: DNS: dns_probe: 1.debian.pool.ntp.org, cast_flags:8, flags:101 Jul 03 09:37:09 volumio go-librespot[1997]: time="2025-07-03T09:37:09+01:00" level=fatal msg="failed running zeroconf" 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" Jul 03 09:37:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 03 09:37:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 03 09:37:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jul 03 09:37:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:12 volumio go-librespot[2051]: go-librespot daemon starting... Jul 03 09:37:12 volumio go-librespot[2052]: time="2025-07-03T09:37:12+01:00" level=info msg="running go-librespot 0.2.0" Jul 03 09:37:12 volumio go-librespot[2052]: time="2025-07-03T09:37:12+01:00" level=debug msg="app state loaded" Jul 03 09:37:12 volumio go-librespot[2052]: time="2025-07-03T09:37:12+01:00" level=debug msg="stored credentials not found" Jul 03 09:37:12 volumio go-librespot[2052]: time="2025-07-03T09:37:12+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 03 09:37:14 volumio volumio-remote-updater[850]: [2025-07-03 09:37:14] [error] handle_read_frame error: asio.system:104 (Connection reset by peer) Jul 03 09:37:14 volumio volumio-remote-updater[850]: [2025-07-03 09:37:14] [disconnect] Disconnect close local:[1006,Connection reset by peer] remote:[1006] Jul 03 09:37:14 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jul 03 09:37:14 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jul 03 09:37:14 volumio systemd[1]: volumio.service: Consumed 18.729s CPU time. Jul 03 09:37:14 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jul 03 09:37:14 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jul 03 09:37:15 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Jul 03 09:37:15 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jul 03 09:37:15 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jul 03 09:37:15 volumio systemd[1]: volumio.service: Consumed 18.729s CPU time. Jul 03 09:37:15 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jul 03 09:37:15 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jul 03 09:37:15 volumio volumio[2089]: info: ------------------------------------------- Jul 03 09:37:15 volumio volumio[2089]: info: ----- Volumio3 ---- Jul 03 09:37:15 volumio volumio[2089]: info: ------------------------------------------- Jul 03 09:37:15 volumio volumio[2089]: info: ----- System startup ---- Jul 03 09:37:15 volumio volumio[2089]: info: ------------------------------------------- Jul 03 09:37:15 volumio volumio[2089]: info: MYVOLUMIO Environment detected Jul 03 09:37:15 volumio volumio[2089]: info: Plugin folders cleanup Jul 03 09:37:15 volumio volumio[2089]: info: Scanning into folder /volumio/app/plugins/ Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category audio_interface Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category miscellanea Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category music_service Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category plugins.json Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category system_controller Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category user_interface Jul 03 09:37:15 volumio volumio[2089]: info: Scanning into folder /data/plugins/ Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category music_service Jul 03 09:37:15 volumio volumio[2089]: info: Scanning category system_controller Jul 03 09:37:15 volumio volumio[2089]: info: Plugin folders cleanup completed Jul 03 09:37:15 volumio volumio[2089]: info: ------------------------------------------- Jul 03 09:37:15 volumio volumio[2089]: info: ----- Core plugins startup ---- Jul 03 09:37:15 volumio volumio[2089]: info: ------------------------------------------- Jul 03 09:37:15 volumio volumio[2089]: info: Loading plugins from folder /volumio/app/plugins/ Jul 03 09:37:15 volumio volumio[2089]: info: Adding plugin upnp to MyMusic Plugins Jul 03 09:37:15 volumio volumio[2089]: info: Adding plugin airplay_emulation to MyMusic Plugins Jul 03 09:37:15 volumio volumio[2089]: info: Adding plugin upnp_browser to MyMusic Plugins Jul 03 09:37:15 volumio volumio[2089]: info: Loading plugins from folder /data/plugins/ Jul 03 09:37:15 volumio volumio[2089]: info: Loading plugin "system"... Jul 03 09:37:15 volumio volumio[2089]: info: Loading plugin "appearance"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "network"... Jul 03 09:37:16 volumio volumio[2089]: info: Refreshing Cached IP Addresses Jul 03 09:37:16 volumio sudo[2117]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 03 09:37:16 volumio sudo[2117]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:16 volumio sudo[2119]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 03 09:37:16 volumio sudo[2119]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:16 volumio sudo[2119]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:16 volumio sudo[2117]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "services"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "alsa_controller"... Jul 03 09:37:16 volumio sudo[2126]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jul 03 09:37:16 volumio sudo[2126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:16 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "wizard"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "networkfs"... Jul 03 09:37:16 volumio volumio[2089]: info: Cannot mount NAS Music at system boot, trial number 1 ,retrying in 5 seconds Jul 03 09:37:16 volumio volumio[2089]: info: Starting Udev Watcher for removable devices Jul 03 09:37:16 volumio volumio[2089]: info: Ignoring mount for partition: boot Jul 03 09:37:16 volumio volumio[2089]: info: Ignoring mount for partition: volumio Jul 03 09:37:16 volumio volumio[2089]: info: Ignoring mount for partition: volumio_data Jul 03 09:37:16 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "volumio_command_line_client"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "upnp"... Jul 03 09:37:16 volumio volumio[2089]: info: [1751531836292] Starting Upmpd Daemon Jul 03 09:37:16 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "my_music"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "mpd"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "upnp_browser"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "alarm-clock"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "airplay_emulation"... Jul 03 09:37:16 volumio volumio[2089]: info: Starting Shairport Sync Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "last_100"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "webradio"... Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "i2s_dacs"... Jul 03 09:37:16 volumio volumio[2089]: info: I2S DAC not set, start Auto-detection Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "volumiodiscovery"... Jul 03 09:37:16 volumio volumio[2089]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 03 09:37:16 volumio volumio[2089]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 03 09:37:16 volumio volumio[2089]: *** WARNING *** For more information see Jul 03 09:37:16 volumio volumio[2089]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 03 09:37:16 volumio volumio[2089]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 03 09:37:16 volumio volumio[2089]: *** WARNING *** For more information see Jul 03 09:37:16 volumio node[2089]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jul 03 09:37:16 volumio node[2089]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 03 09:37:16 volumio node[2089]: *** WARNING *** For more information see Jul 03 09:37:16 volumio node[2089]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jul 03 09:37:16 volumio node[2089]: *** WARNING *** Please fix your application to use the native API of Avahi! Jul 03 09:37:16 volumio node[2089]: *** WARNING *** For more information see Jul 03 09:37:16 volumio volumio[2089]: info: Applying required configuration parameters for plugin volumiodiscovery Jul 03 09:37:16 volumio volumio[2089]: info: Discovery: Started advertising with name: Volumio Jul 03 09:37:16 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 03 09:37:16 volumio volumio[2089]: info: Loading plugin "spop"... Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "ytmusic"... Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "outputs"... Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "albumart"... Jul 03 09:37:17 volumio volumio[2089]: info: Plugin example_plugin is not enabled Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "inputs"... Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "updater_comm"... Jul 03 09:37:17 volumio volumio[2089]: info: Plugin mpdemulation is not enabled Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "rest_api"... Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "websocket"... Jul 03 09:37:17 volumio volumio[2089]: info: Starting Socket.io Server version 1.7.4 Jul 03 09:37:17 volumio volumio[2089]: info: Loading plugin "backup_restore"... Jul 03 09:37:18 volumio volumio[2089]: info: Applying required configuration parameters for plugin backup_restore Jul 03 09:37:18 volumio volumio[2089]: info: Loading i18n strings for locale en Jul 03 09:37:18 volumio volumio[2089]: Updating browse sources language Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::initPlayerControls Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 03 09:37:18 volumio volumio[2149]: Forking 3 albumart workers Jul 03 09:37:18 volumio volumio[2089]: Express server listening on port 3000 Jul 03 09:37:18 volumio volumio[2089]: [Metrics] WebUI: 2s 557.48ms Jul 03 09:37:18 volumio volumio[2089]: info: CoreStateMachine::resetVolumioState Jul 03 09:37:18 volumio volumio[2089]: info: CoreStateMachine::getcurrentVolume Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioRetrievevolume Jul 03 09:37:18 volumio volumio[2089]: info: CoreStateMachine::pushState Jul 03 09:37:18 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioPushState Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: Cannot read play queue from file Jul 03 09:37:18 volumio volumio[2089]: info: Volumio Network Manager: Network status updated: 1 Jul 03 09:37:18 volumio volumio[2089]: info: CoreStateMachine::setRepeat null single undefined Jul 03 09:37:18 volumio volumio[2089]: info: CoreStateMachine::pushState Jul 03 09:37:18 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioPushState Jul 03 09:37:18 volumio volumio[2089]: info: CoreStateMachine::setRandom null Jul 03 09:37:18 volumio volumio[2089]: info: CoreStateMachine::pushState Jul 03 09:37:18 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioPushState Jul 03 09:37:18 volumio volumio[2089]: info: Setting Device type: Raspberry PI Jul 03 09:37:18 volumio volumio[2089]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jul 03 09:37:18 volumio volumio[2089]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c04170 Jul 03 09:37:18 volumio volumio[2089]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jul 03 09:37:18 volumio volumio[2089]: info: Completed loading Core Plugins Jul 03 09:37:18 volumio volumio[2089]: info: Preparing to generate the ALSA configuration file Jul 03 09:37:18 volumio volumio[2089]: info: Asound.conf file unchanged, so no further update is needed Jul 03 09:37:18 volumio volumio[2089]: info: Output device has changed, restarting MPD Jul 03 09:37:18 volumio volumio[2089]: info: Output device has changed, restarting Shairport Sync Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:18 volumio sudo[2207]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 03 09:37:18 volumio sudo[2207]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio sudo[2209]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 03 09:37:18 volumio sudo[2209]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio sudo[2207]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:18 volumio volumio[2089]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 03 09:37:18 volumio volumio[2089]: info: ___________ START PLUGINS ___________ Jul 03 09:37:18 volumio volumio[2089]: info: ControllerMpd::onStart: Initializing MPD Jul 03 09:37:18 volumio volumio[2089]: info: Creating MPD Configuration file Jul 03 09:37:18 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 03 09:37:18 volumio volumio[2089]: info: [1751531838324] CoreMusicLibrary::Adding element Media Servers Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 09:37:18 volumio sudo[2217]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jul 03 09:37:18 volumio sudo[2217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:18 volumio sudo[2217]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:18 volumio sudo[2219]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jul 03 09:37:18 volumio sudo[2219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio volumio[2089]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 03 09:37:18 volumio volumio[2089]: info: [1751531838407] CoreMusicLibrary::Adding element Last_100 Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 03 09:37:18 volumio volumio[2089]: info: [1751531838409] CoreMusicLibrary::Adding element Webradio Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 03 09:37:18 volumio volumio[2089]: info: Initializing BBC Radios Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: Creating Spotify config file Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 03 09:37:18 volumio volumio[2089]: info: [1751531838473] CoreMusicLibrary::Adding element YouTube Music Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 09:37:18 volumio volumio[2089]: Cannot find translation for source YouTube Music Jul 03 09:37:18 volumio volumio[2089]: info: Volumio Calling Home Jul 03 09:37:18 volumio systemd[1]: mpd.service: Deactivated successfully. Jul 03 09:37:18 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jul 03 09:37:18 volumio systemd[1]: mpd.service: Consumed 1.824s CPU time. Jul 03 09:37:18 volumio systemd[1]: mpd.socket: Deactivated successfully. Jul 03 09:37:18 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jul 03 09:37:18 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jul 03 09:37:18 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jul 03 09:37:18 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jul 03 09:37:18 volumio volumio[2159]: Starting albumart workers Jul 03 09:37:18 volumio sudo[2249]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jul 03 09:37:18 volumio sudo[2249]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jul 03 09:37:18 volumio sudo[2249]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:18 volumio volumio[2166]: Starting albumart workers Jul 03 09:37:18 volumio volumio[2163]: Starting albumart workers Jul 03 09:37:18 volumio volumio[2089]: info: MPD Permissions set Jul 03 09:37:18 volumio volumio[2089]: info: MPD Permissions set Jul 03 09:37:18 volumio volumio[2089]: info: Spotify config file written Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio sudo[2253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 03 09:37:18 volumio sudo[2253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jul 03 09:37:18 volumio systemd[1]: go-librespot-daemon.service: Killing process 2053 (go-librespot) with signal SIGKILL. Jul 03 09:37:18 volumio systemd[1]: go-librespot-daemon.service: Killing process 2056 (go-librespot) with signal SIGKILL. Jul 03 09:37:18 volumio systemd[1]: go-librespot-daemon.service: Killing process 2057 (go-librespot) with signal SIGKILL. Jul 03 09:37:18 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jul 03 09:37:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:18 volumio go-librespot[2260]: go-librespot daemon starting... Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:18 volumio volumio[2089]: info: No need to fix Spotify hosts Jul 03 09:37:18 volumio go-librespot[2267]: time="2025-07-03T09:37:18+01:00" level=info msg="running go-librespot 0.2.0" Jul 03 09:37:18 volumio go-librespot[2267]: time="2025-07-03T09:37:18+01:00" level=debug msg="app state loaded" Jul 03 09:37:18 volumio go-librespot[2267]: time="2025-07-03T09:37:18+01:00" level=debug msg="stored credentials not found" Jul 03 09:37:18 volumio go-librespot[2267]: time="2025-07-03T09:37:18+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 03 09:37:18 volumio sudo[2253]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:18 volumio volumio[2089]: info: Starting Shairport Sync Jul 03 09:37:18 volumio volumio[2089]: info: Starting Shairport Sync Jul 03 09:37:18 volumio volumio[2089]: info: Starting Shairport Sync Jul 03 09:37:18 volumio sudo[2279]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 03 09:37:18 volumio sudo[2279]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio sudo[2283]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 03 09:37:18 volumio sudo[2283]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jul 03 09:37:18 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jul 03 09:37:18 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jul 03 09:37:18 volumio systemd[1]: shairport-sync.service: Consumed 1.604s CPU time. Jul 03 09:37:18 volumio sudo[2281]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 03 09:37:18 volumio sudo[2281]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:18 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jul 03 09:37:18 volumio sudo[2279]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:18 volumio volumio[2089]: info: Shairport-Sync Started Jul 03 09:37:18 volumio volumio[2089]: Error adding Membership: Error: addMembership EINVAL Jul 03 09:37:19 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jul 03 09:37:19 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jul 03 09:37:19 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jul 03 09:37:19 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jul 03 09:37:19 volumio sudo[2283]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:19 volumio volumio[2089]: info: Shairport-Sync Started Jul 03 09:37:19 volumio sudo[2281]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:19 volumio volumio[2089]: info: Shairport-Sync Started Jul 03 09:37:19 volumio mpd[2251]: 2025-07-03T09:37:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 03 09:37:19 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jul 03 09:37:19 volumio sudo[2219]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:19 volumio sudo[2209]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:19 volumio volumio[2089]: info: Completed starting Core Plugins Jul 03 09:37:19 volumio volumio[2089]: info: ------------------------------------------- Jul 03 09:37:19 volumio volumio[2089]: info: ----- MyVolumio plugins startup ---- Jul 03 09:37:19 volumio volumio[2089]: info: ------------------------------------------- Jul 03 09:37:19 volumio volumio[2089]: info: [MyVolumio PluginManager] Fetching plans data.... Jul 03 09:37:19 volumio volumio[2089]: error: MPD error: The expression evaluated to a falsy value: Jul 03 09:37:19 volumio volumio[2089]: assert.ok(self.idling) Jul 03 09:37:19 volumio volumio[2089]: error: The expression evaluated to a falsy value: Jul 03 09:37:19 volumio volumio[2089]: assert.ok(self.idling) Jul 03 09:37:19 volumio volumio[2089]: error: updateQueue error: null Jul 03 09:37:19 volumio volumio[2089]: info: MPD running with PID2251 Jul 03 09:37:19 volumio volumio[2089]: ,establishing connection Jul 03 09:37:19 volumio volumio[2089]: error: updateQueue error: null Jul 03 09:37:19 volumio volumio-remote-updater[850]: [2025-07-03 09:37:19] [connect] Successful connection Jul 03 09:37:19 volumio volumio-remote-updater[850]: [2025-07-03 09:37:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1751531839 101 Jul 03 09:37:19 volumio volumio[2089]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jul 03 09:37:20 volumio sudo[2126]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:21 volumio ntpd[1003]: DNS: dns_check: processing 1.debian.pool.ntp.org, 8, 101 Jul 03 09:37:21 volumio ntpd[1003]: DNS: dns_check: DNS error: -11, System error Jul 03 09:37:21 volumio ntpd[1003]: DNS: dns_take_status: 1.debian.pool.ntp.org=>error, 12 Jul 03 09:37:21 volumio volumio[2089]: info: Cannot mount NAS Music at system boot, trial number 2 ,retrying in 5 seconds Jul 03 09:37:21 volumio ntpd[1003]: DNS: dns_probe: 0.debian.pool.ntp.org, cast_flags:8, flags:101 Jul 03 09:37:21 volumio volumio[2089]: info: go-librespot daemon successfully initialized Jul 03 09:37:21 volumio volumio[2089]: info: Discovery: A device disappeared from network Jul 03 09:37:21 volumio volumio[2089]: info: Discovery: Browse raised the following error TypeError: Cannot read properties of undefined (reading 'toLowerCase') Jul 03 09:37:24 volumio volumio[2089]: info: Initializing connection to go-librespot Websocket Jul 03 09:37:25 volumio volumio[2089]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jul 03 09:37:26 volumio volumio[2089]: info: Cannot mount NAS Music at system boot, trial number 3 ,retrying in 5 seconds Jul 03 09:37:26 volumio sudo[2349]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 03 09:37:26 volumio sudo[2349]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:26 volumio sudo[2351]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 03 09:37:26 volumio sudo[2351]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:26 volumio sudo[2349]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:26 volumio sudo[2351]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:28 volumio systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 03 09:37:28 volumio sudo[2357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jul 03 09:37:28 volumio sudo[2357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:37:28 volumio sudo[2357]: pam_unix(sudo:session): session closed for user root Jul 03 09:37:29 volumio volumio[2089]: info: Upmpdcli Daemon Started Jul 03 09:37:30 volumio go-librespot[2267]: time="2025-07-03T09:37:30+01:00" level=fatal msg="failed running zeroconf" 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" Jul 03 09:37:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 03 09:37:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 03 09:37:31 volumio volumio[2089]: info: Discovery: A device disappeared from network Jul 03 09:37:31 volumio volumio[2089]: info: Discovery: Browse raised the following error TypeError: Cannot read properties of undefined (reading 'toLowerCase') Jul 03 09:37:31 volumio volumio[2089]: info: Cannot mount NAS Music at system boot, trial number 4 ,retrying in 5 seconds Jul 03 09:37:33 volumio ntpd[1003]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Jul 03 09:37:33 volumio ntpd[1003]: DNS: dns_check: DNS error: -11, System error Jul 03 09:37:33 volumio ntpd[1003]: DNS: dns_take_status: 0.debian.pool.ntp.org=>error, 12 Jul 03 09:37:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jul 03 09:37:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:33 volumio go-librespot[2359]: go-librespot daemon starting... Jul 03 09:37:33 volumio go-librespot[2360]: time="2025-07-03T09:37:33+01:00" level=info msg="running go-librespot 0.2.0" Jul 03 09:37:33 volumio go-librespot[2360]: time="2025-07-03T09:37:33+01:00" level=debug msg="app state loaded" Jul 03 09:37:33 volumio go-librespot[2360]: time="2025-07-03T09:37:33+01:00" level=debug msg="stored credentials not found" Jul 03 09:37:33 volumio go-librespot[2360]: time="2025-07-03T09:37:33+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 03 09:37:36 volumio volumio[2089]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Jul 03 09:37:39 volumio volumio[2089]: error: MyVolumio Plugin failed to start in a timely fashion Jul 03 09:37:39 volumio volumio[2089]: [Metrics] CommandRouter: 23s 999.37ms Jul 03 09:37:39 volumio volumio[2089]: info: CoreCommandRouter::volumiosetStartupVolume Jul 03 09:37:39 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 09:37:39 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:39 volumio volumio[2089]: info: CoreCommandRouter::Close All Modals sent Jul 03 09:37:39 volumio volumio[2089]: info: CoreCommandRouter::Close All Modals sent Jul 03 09:37:39 volumio volumio[2089]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Jul 03 09:37:39 volumio volumio[2089]: aplay: main:831: audio open error: Unknown error 524 Jul 03 09:37:40 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jul 03 09:37:40 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jul 03 09:37:40 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jul 03 09:37:40 volumio volumio[2089]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.014&uuid=4ee25fd7e4d182a89c50394ac68768d6" http://updates.volumio.org/downloader-v1/track-device Jul 03 09:37:40 volumio volumio[2089]: % Total % Received % Xferd Average Speed Time Time Time Current Jul 03 09:37:40 volumio volumio[2089]: Dload Upload Total Spent Left Speed Jul 03 09:37:40 volumio volumio[2089]: [1.0K blob data] Jul 03 09:37:40 volumio volumio[2089]: retrying in 5 seconds, trial 0 Jul 03 09:37:40 volumio volumio[2089]: info: Volumio Calling Home Jul 03 09:37:42 volumio volumio[2089]: info: Discovery: adding 7da6a17a-b7f6-4d7c-b46b-6fd118d23e8e Jul 03 09:37:42 volumio volumio[2089]: info: Discovery: Found device Volumio - Old Jul 03 09:37:42 volumio volumio[2089]: info: Discovery: Connecting to remote: 192.168.0.169 Jul 03 09:37:42 volumio volumio[2089]: info: Discovery: adding 42726e1c-0f86-42b7-a80c-f768d91e4d78 Jul 03 09:37:42 volumio volumio[2089]: info: Discovery: Found device Volumio Jul 03 09:37:42 volumio volumio[2089]: info: Discovery: Connecting to remote: 192.168.0.229 Jul 03 09:37:42 volumio volumio[2089]: info: Discovery: Connected to remote: 192.168.0.169 Jul 03 09:37:44 volumio volumio[2089]: info: Discovery: Connected to remote: 192.168.0.229 Jul 03 09:37:45 volumio go-librespot[2360]: time="2025-07-03T09:37:45+01:00" level=fatal msg="failed running zeroconf" 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" Jul 03 09:37:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 03 09:37:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 03 09:37:46 volumio volumio[2089]: info: BOOT COMPLETED Jul 03 09:37:48 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 03 09:37:48 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:37:48 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jul 03 09:37:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jul 03 09:37:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:48 volumio volumio[2089]: verbose: New Socket.io Connection to 192.168.0.242:3000 from 192.168.0.169 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jul 03 09:37:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:37:48 volumio go-librespot[2406]: go-librespot daemon starting... Jul 03 09:37:48 volumio go-librespot[2407]: time="2025-07-03T09:37:48+01:00" level=info msg="running go-librespot 0.2.0" Jul 03 09:37:48 volumio go-librespot[2407]: time="2025-07-03T09:37:48+01:00" level=debug msg="app state loaded" Jul 03 09:37:48 volumio go-librespot[2407]: time="2025-07-03T09:37:48+01:00" level=debug msg="stored credentials not found" Jul 03 09:37:48 volumio go-librespot[2407]: time="2025-07-03T09:37:48+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 03 09:37:48 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Jul 03 09:37:48 volumio volumio[2089]: info: CoreCommandRouter::volumioGetState Jul 03 09:37:48 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:37:56 volumio volumio[2089]: verbose: New Socket.io Connection to 192.168.0.242:3000 from 192.168.0.229 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jul 03 09:37:56 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket Jul 03 09:37:56 volumio volumio[2089]: info: CoreCommandRouter::volumioGetState Jul 03 09:37:56 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:37:57 volumio go-librespot[2407]: time="2025-07-03T09:37:57+01:00" level=fatal msg="failed running zeroconf" 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" Jul 03 09:37:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 03 09:37:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 03 09:38:00 volumio systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 03 09:38:00 volumio dbus-daemon[834]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.36' (uid=0 pid=2428 comm="timedatectl show --property=NTPSynchronized --valu") Jul 03 09:38:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jul 03 09:38:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:38:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:38:00 volumio go-librespot[2430]: go-librespot daemon starting... Jul 03 09:38:00 volumio systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 03 09:38:00 volumio go-librespot[2432]: time="2025-07-03T09:38:00+01:00" level=info msg="running go-librespot 0.2.0" Jul 03 09:38:00 volumio go-librespot[2432]: time="2025-07-03T09:38:00+01:00" level=debug msg="app state loaded" Jul 03 09:38:00 volumio go-librespot[2432]: time="2025-07-03T09:38:00+01:00" level=debug msg="stored credentials not found" Jul 03 09:38:00 volumio go-librespot[2432]: time="2025-07-03T09:38:00+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 03 09:38:00 volumio dbus-daemon[834]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 03 09:38:00 volumio systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 03 09:38:00 volumio setdatetime-helper.sh[2427]: Time is already synchronized. Jul 03 09:38:00 volumio systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 03 09:38:00 volumio systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 03 09:38:01 volumio volumio[2089]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.014&uuid=4ee25fd7e4d182a89c50394ac68768d6" http://updates.volumio.org/downloader-v1/track-device Jul 03 09:38:01 volumio volumio[2089]: % Total % Received % Xferd Average Speed Time Time Time Current Jul 03 09:38:01 volumio volumio[2089]: Dload Upload Total Spent Left Speed Jul 03 09:38:01 volumio volumio[2089]: [1001B blob data] Jul 03 09:38:01 volumio volumio[2089]: retrying in 5 seconds, trial 1 Jul 03 09:38:01 volumio volumio[2089]: info: Volumio Calling Home Jul 03 09:38:07 volumio volumio[2089]: info: Discovery: adding 4a3fd924-7fbb-4d80-b939-168d11577f15 Jul 03 09:38:07 volumio volumio[2089]: info: Discovery: Found device Volumio Jul 03 09:38:07 volumio volumio[2089]: info: CoreCommandRouter::volumioGetState Jul 03 09:38:07 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:38:07 volumio volumio[2089]: info: Discovery: this is already registered, 4a3fd924-7fbb-4d80-b939-168d11577f15 Jul 03 09:38:07 volumio volumio[2089]: info: Discovery: Found device Volumio Jul 03 09:38:07 volumio volumio[2089]: info: CoreCommandRouter::volumioGetState Jul 03 09:38:07 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:38:07 volumio volumio[2089]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jul 03 09:38:10 volumio go-librespot[2432]: time="2025-07-03T09:38:10+01:00" level=fatal msg="failed running zeroconf" 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" Jul 03 09:38:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 03 09:38:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 03 09:38:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jul 03 09:38:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:38:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jul 03 09:38:13 volumio go-librespot[2455]: go-librespot daemon starting... Jul 03 09:38:13 volumio go-librespot[2456]: time="2025-07-03T09:38:13+01:00" level=info msg="running go-librespot 0.2.0" Jul 03 09:38:13 volumio go-librespot[2456]: time="2025-07-03T09:38:13+01:00" level=debug msg="app state loaded" Jul 03 09:38:13 volumio go-librespot[2456]: time="2025-07-03T09:38:13+01:00" level=debug msg="stored credentials not found" Jul 03 09:38:13 volumio go-librespot[2456]: time="2025-07-03T09:38:13+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 03 09:38:22 volumio volumio[2089]: info: Discovery: this is already registered, 7da6a17a-b7f6-4d7c-b46b-6fd118d23e8e Jul 03 09:38:22 volumio volumio[2089]: info: Discovery: Found device Volumio - Old Jul 03 09:38:22 volumio go-librespot[2456]: time="2025-07-03T09:38:22+01:00" level=debug msg="new websocket client" Jul 03 09:38:22 volumio volumio[2089]: info: Connection to go-librespot Websocket established Jul 03 09:38:22 volumio volumio[2089]: info: Discovery: this is already registered, 42726e1c-0f86-42b7-a80c-f768d91e4d78 Jul 03 09:38:22 volumio volumio[2089]: info: Discovery: Found device Volumio Jul 03 09:38:22 volumio volumio[2089]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Jul 03 09:38:22 volumio volumio[2089]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jul 03 09:38:24 volumio volumio[2089]: info: Discovery: this is already registered, 4a3fd924-7fbb-4d80-b939-168d11577f15 Jul 03 09:38:24 volumio volumio[2089]: info: Discovery: Found device Volumio Jul 03 09:38:24 volumio volumio[2089]: info: CoreCommandRouter::volumioGetState Jul 03 09:38:24 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:38:24 volumio volumio[2089]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 03 09:38:24 volumio volumio[2089]: info: CoreCommandRouter::volumioGetState Jul 03 09:38:24 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jul 03 09:38:24 volumio volumio[2089]: info: Adding plugin bluetooth to MyMusic Plugins Jul 03 09:38:24 volumio volumio[2089]: info: Adding plugin multiroom to MyMusic Plugins Jul 03 09:38:24 volumio volumio[2089]: info: Adding plugin metavolumio to MyMusic Plugins Jul 03 09:38:24 volumio volumio[2089]: info: Adding plugin cd_controller to MyMusic Plugins Jul 03 09:38:24 volumio volumio[2089]: info: Adding plugin qobuzconnect to MyMusic Plugins Jul 03 09:38:24 volumio volumio[2089]: info: Adding plugin smart_inputs to MyMusic Plugins Jul 03 09:38:24 volumio volumio[2089]: info: Adding plugin tidalconnect to MyMusic Plugins Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jul 03 09:38:24 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:38:24 volumio volumio[2089]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 09:38:24 volumio volumio[2089]: info: Starting MyVolumio Remote Streaming Endpoints Jul 03 09:38:24 volumio volumio[2089]: info: MyVolumio login type: Token Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jul 03 09:38:24 volumio volumio[2089]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jul 03 09:38:25 volumio volumio[2089]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jul 03 09:38:25 volumio volumio[2089]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jul 03 09:38:25 volumio volumio[2089]: info: Streaming services startup Jul 03 09:38:25 volumio volumio[2089]: info: Starting Streaming Daemon Jul 03 09:38:25 volumio sudo[2480]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jul 03 09:38:25 volumio sudo[2480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jul 03 09:38:25 volumio volumio[2089]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jul 03 09:38:25 volumio sudo[2480]: pam_unix(sudo:session): session closed for user root Jul 03 09:38:25 volumio volumio[2089]: info: Getting Spotify volume Jul 03 09:38:25 volumio volumio[2089]: error: Cannot start Volumio Streaming Daemon Jul 03 09:38:25 volumio volumio[2089]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jul 03 09:38:25 volumio volumio[2089]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jul 03 09:38:25 volumio volumio[2089]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Jul 03 09:38:25 volumio volumio[2089]: info: CoreCommandRouter::volumioGetState Jul 03 09:38:25 volumio volumio[2089]: info: CorePlayQueue::getTrack 0 Jul 03 09:38:25 volumio go-librespot[2456]: time="2025-07-03T09:38:25+01:00" level=fatal msg="failed running zeroconf" 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" Jul 03 09:38:25 volumio volumio[2089]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 03 09:38:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 03 09:38:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 03 09:38:25 volumio volumio[2089]: Error: socket hang up Jul 03 09:38:25 volumio volumio[2089]: at connResetException (node:internal/errors:720:14) Jul 03 09:38:25 volumio volumio[2089]: at Socket.socketOnEnd (node:_http_client:519:23) Jul 03 09:38:25 volumio volumio[2089]: at Socket.emit (node:events:526:35) Jul 03 09:38:25 volumio volumio[2089]: at endReadableNT (node:internal/streams/readable:1376:12) Jul 03 09:38:25 volumio volumio[2089]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jul 03 09:38:25 volumio volumio[2089]: code: 'ECONNRESET', Jul 03 09:38:25 volumio volumio[2089]: response: undefined Jul 03 09:38:25 volumio volumio[2089]: } Jul 03 09:38:25 volumio volumio[2089]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 03 09:38:25 volumio sudo[2500]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-07-03 09:37' Jul 03 09:38:25 volumio sudo[2500]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f9454895cc8e2f1971c705a815a7226e021e37d7" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1fc282af1865fae9b40239cedf2cc17c112eef0d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jun 28 16:48:46 UTC 2025" VOLUMIO_VERSION="4.014" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="1b557e4869cd2eea14f4113140ecea1c"