Mar 27 10:28:01 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:01] [connect] Successful connection Mar 27 10:28:16 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:16] [connect] Successful connection Mar 27 10:28:20 volumio44 go-librespot[32494]: time="2026-03-27T10:28:20+09: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\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)" Mar 27 10:28:20 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:20 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:28:23 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Mar 27 10:28:23 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:23 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:23 volumio44 go-librespot[32545]: go-librespot daemon starting... Mar 27 10:28:23 volumio44 go-librespot[32546]: time="2026-03-27T10:28:23+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:23 volumio44 go-librespot[32546]: time="2026-03-27T10:28:23+09:00" level=debug msg="app state loaded" Mar 27 10:28:23 volumio44 go-librespot[32546]: time="2026-03-27T10:28:23+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:24 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:24.508+09:00 level=ERROR msg="failed reading message" error="read tcp 127.0.0.1:50322->127.0.0.1:3000: read: connection reset by peer" Mar 27 10:28:24 volumio44 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:24 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:24.510+09:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 27 10:28:24 volumio44 systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 27 10:28:24 volumio44 systemd[1]: volumio.service: Consumed 10min 22.125s CPU time. Mar 27 10:28:24 volumio44 systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 27 10:28:24 volumio44 systemd[1]: dynamicswap.service: Deactivated successfully. Mar 27 10:28:24 volumio44 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Mar 27 10:28:24 volumio44 systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 27 10:28:24 volumio44 systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 27 10:28:24 volumio44 systemd[1]: volumio.service: Consumed 10min 22.125s CPU time. Mar 27 10:28:24 volumio44 systemd[1]: Started volumio.service - Volumio Backend Module. Mar 27 10:28:24 volumio44 systemd[1]: dynamicswap.service: Deactivated successfully. Mar 27 10:28:25 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:25.511+09:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 27 10:28:25 volumio44 volumio[32592]: info: ------------------------------------------- Mar 27 10:28:25 volumio44 volumio[32592]: info: ----- Volumio3 ---- Mar 27 10:28:25 volumio44 volumio[32592]: info: ------------------------------------------- Mar 27 10:28:25 volumio44 volumio[32592]: info: ----- System startup ---- Mar 27 10:28:25 volumio44 volumio[32592]: info: ------------------------------------------- Mar 27 10:28:26 volumio44 volumio[32592]: info: MYVOLUMIO Environment detected Mar 27 10:28:26 volumio44 volumio[32592]: info: Plugin folders cleanup Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning into folder /volumio/app/plugins/ Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning category audio_interface Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning category miscellanea Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning category music_service Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning category plugins.json Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning category system_controller Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning category user_interface Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning into folder /data/plugins/ Mar 27 10:28:26 volumio44 volumio[32592]: info: Scanning category music_service Mar 27 10:28:26 volumio44 volumio[32592]: info: Plugin folders cleanup completed Mar 27 10:28:26 volumio44 volumio[32592]: info: ------------------------------------------- Mar 27 10:28:26 volumio44 volumio[32592]: info: ----- Core plugins startup ---- Mar 27 10:28:26 volumio44 volumio[32592]: info: ------------------------------------------- Mar 27 10:28:26 volumio44 volumio[32592]: info: Loading plugins from folder /volumio/app/plugins/ Mar 27 10:28:26 volumio44 volumio[32592]: info: Adding plugin upnp to MyMusic Plugins Mar 27 10:28:26 volumio44 volumio[32592]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 27 10:28:26 volumio44 volumio[32592]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 27 10:28:26 volumio44 volumio[32592]: info: Loading plugins from folder /data/plugins/ Mar 27 10:28:26 volumio44 volumio[32592]: info: Loading plugin "system"... Mar 27 10:28:26 volumio44 volumio[32592]: info: Loading plugin "appearance"... Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "network"... Mar 27 10:28:27 volumio44 volumio[32592]: info: Refreshing Cached IP Addresses Mar 27 10:28:27 volumio44 sudo[32621]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 10:28:27 volumio44 sudo[32623]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 10:28:27 volumio44 sudo[32623]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:27 volumio44 sudo[32621]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "services"... Mar 27 10:28:27 volumio44 sudo[32623]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "volumio5onboarding"... Mar 27 10:28:27 volumio44 sudo[32621]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:27 volumio44 sudo[32630]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 27 10:28:27 volumio44 sudo[32630]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "alsa_controller"... Mar 27 10:28:27 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "wizard"... Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "networkfs"... Mar 27 10:28:27 volumio44 volumio[32592]: info: Starting Udev Watcher for removable devices Mar 27 10:28:27 volumio44 volumio[32592]: info: Ignoring mount for partition: boot Mar 27 10:28:27 volumio44 volumio[32592]: info: Ignoring mount for partition: volumio Mar 27 10:28:27 volumio44 volumio[32592]: info: Ignoring mount for partition: volumio_data Mar 27 10:28:27 volumio44 volumio[32592]: info: Mounting Device 3266-3164 Mar 27 10:28:27 volumio44 sudo[32660]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/3266-3164 -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 27 10:28:27 volumio44 sudo[32660]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:27 volumio44 sudo[32660]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:27 volumio44 volumio[32592]: mount: /media/3266-3164: /dev/sda1 already mounted on /media/3266-3164. Mar 27 10:28:27 volumio44 volumio[32592]: dmesg(1) may have more information after failed mount system call. Mar 27 10:28:27 volumio44 volumio[32592]: error: Failed to mount 3266-3164: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/3266-3164" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 27 10:28:27 volumio44 volumio[32592]: mount: /media/3266-3164: /dev/sda1 already mounted on /media/3266-3164. Mar 27 10:28:27 volumio44 volumio[32592]: dmesg(1) may have more information after failed mount system call. Mar 27 10:28:27 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "volumio_command_line_client"... Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "upnp"... Mar 27 10:28:27 volumio44 volumio[32592]: info: [1774574907688] Starting Upmpd Daemon Mar 27 10:28:27 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "my_music"... Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "mpd"... Mar 27 10:28:27 volumio44 volumio[32592]: info: Loading plugin "upnp_browser"... Mar 27 10:28:28 volumio44 volumio[32592]: info: Starting UPNP Browser Mar 27 10:28:28 volumio44 volumio[32592]: info: Loading plugin "alarm-clock"... Mar 27 10:28:28 volumio44 volumio[32592]: info: Loading plugin "airplay_emulation"... Mar 27 10:28:28 volumio44 volumio[32592]: info: Starting Shairport Sync Mar 27 10:28:28 volumio44 volumio[32592]: info: Loading plugin "last_100"... Mar 27 10:28:28 volumio44 volumio[32592]: info: Loading plugin "webradio"... Mar 27 10:28:29 volumio44 volumio[32592]: info: Loading plugin "i2s_dacs"... Mar 27 10:28:29 volumio44 volumio[32592]: info: Loading plugin "volumiodiscovery"... Mar 27 10:28:29 volumio44 volumio[32592]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:29 volumio44 volumio[32592]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:29 volumio44 node[32592]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:29 volumio44 volumio[32592]: *** WARNING *** For more information see Mar 27 10:28:29 volumio44 volumio[32592]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:29 volumio44 volumio[32592]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:29 volumio44 volumio[32592]: *** WARNING *** For more information see Mar 27 10:28:29 volumio44 node[32592]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:29 volumio44 node[32592]: *** WARNING *** For more information see Mar 27 10:28:29 volumio44 node[32592]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:29 volumio44 node[32592]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:29 volumio44 node[32592]: *** WARNING *** For more information see Mar 27 10:28:29 volumio44 volumio[32592]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 27 10:28:29 volumio44 volumio[32592]: info: Discovery: Started advertising with name: Volumio44 Mar 27 10:28:29 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 10:28:29 volumio44 volumio[32592]: info: Loading plugin "spop"... Mar 27 10:28:29 volumio44 volumio[32592]: info: Plugin ytmusic is not enabled Mar 27 10:28:29 volumio44 volumio[32592]: info: Loading plugin "outputs"... Mar 27 10:28:29 volumio44 volumio[32592]: info: Loading plugin "albumart"... Mar 27 10:28:29 volumio44 volumio[32592]: info: Plugin example_plugin is not enabled Mar 27 10:28:29 volumio44 volumio[32592]: info: Loading plugin "inputs"... Mar 27 10:28:29 volumio44 volumio[32592]: info: Loading plugin "updater_comm"... Mar 27 10:28:30 volumio44 volumio[32592]: info: Plugin mpdemulation is not enabled Mar 27 10:28:30 volumio44 volumio[32592]: info: Loading plugin "rest_api"... Mar 27 10:28:30 volumio44 volumio[32592]: info: Loading plugin "websocket"... Mar 27 10:28:30 volumio44 volumio[32592]: info: Starting Socket.io Server version 1.7.4 Mar 27 10:28:30 volumio44 volumio[32592]: info: Loading plugin "jp_radio"... Mar 27 10:28:30 volumio44 volumio[32664]: Forking 3 albumart workers Mar 27 10:28:30 volumio44 volumio[32674]: Starting albumart workers Mar 27 10:28:31 volumio44 volumio[32676]: Starting albumart workers Mar 27 10:28:31 volumio44 volumio[32675]: Starting albumart workers Mar 27 10:28:31 volumio44 sudo[32630]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:31 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:31] [connect] Successful connection Mar 27 10:28:32 volumio44 volumio[32592]: info: JP_Radio::onVolumioStart Mar 27 10:28:32 volumio44 volumio[32592]: info: Loading i18n strings for locale ja Mar 27 10:28:32 volumio44 volumio[32592]: Updating browse sources language Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::initPlayerControls Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:32 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: Express server listening on port 3000 Mar 27 10:28:33 volumio44 volumio[32592]: [Metrics] WebUI: 7s 301.36ms Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::resetVolumioState Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::getcurrentVolume Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioRetrievevolume Mar 27 10:28:33 volumio44 volumio[32592]: info: Volumio Network Manager: Network status updated: 2 Mar 27 10:28:33 volumio44 volumio[32592]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 27 10:28:33 volumio44 volumio[32592]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 27 10:28:33 volumio44 volumio[32592]: info: Received Get System Info Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:28:33 volumio44 volumio[32592]: info: Discovery: Getting this device information Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:33 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:28:33 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:33] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774574911 101 Mar 27 10:28:33 volumio44 volumio[32592]: 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: 2 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: Reloading queue from file Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:28:33 volumio44 volumio[32592]: info: VolumeController:: Volume=91 Mute =false Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::pushState Mar 27 10:28:33 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::updateTrackBlock Mar 27 10:28:33 volumio44 volumio[32592]: info: CorePlayQueue::getTrackBlock Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioRetrievevolume Mar 27 10:28:33 volumio44 volumio[32592]: info: Setting Device type: Raspberry PI Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::setRepeat null single undefined Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::pushState Mar 27 10:28:33 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::setRandom null Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::pushState Mar 27 10:28:33 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:33 volumio44 volumio[32592]: info: Completed loading Core Plugins Mar 27 10:28:33 volumio44 volumio[32592]: info: Preparing to generate the ALSA configuration file Mar 27 10:28:33 volumio44 volumio[32592]: info: Asound.conf file unchanged, so no further update is needed Mar 27 10:28:33 volumio44 volumio[32592]: info: Output device has changed, restarting MPD Mar 27 10:28:33 volumio44 volumio[32592]: info: Output device has changed, restarting Shairport Sync Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:33 volumio44 sudo[32738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 27 10:28:33 volumio44 sudo[32738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 sudo[32740]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 27 10:28:33 volumio44 sudo[32740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 sudo[32738]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:33 volumio44 volumio[32592]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 27 10:28:33 volumio44 volumio[32592]: info: ___________ START PLUGINS ___________ Mar 27 10:28:33 volumio44 volumio[32592]: info: ControllerMpd::onStart: Initializing MPD Mar 27 10:28:33 volumio44 volumio[32592]: info: Creating MPD Configuration file Mar 27 10:28:33 volumio44 sudo[32748]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 27 10:28:33 volumio44 sudo[32748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 10:28:33 volumio44 systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 10:28:33 volumio44 sudo[32752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 27 10:28:33 volumio44 volumio[32592]: info: [1774574913316] CoreMusicLibrary::Adding element DLNAサーバー Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:33 volumio44 sudo[32752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 sudo[32751]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 27 10:28:33 volumio44 sudo[32751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 sudo[32751]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:33 volumio44 volumio[32592]: info: UPNP Browser: Client initialized successfully Mar 27 10:28:33 volumio44 sudo[32748]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 10:28:33 volumio44 volumio[32592]: info: [1774574913395] CoreMusicLibrary::Adding element Last_100 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 10:28:33 volumio44 volumio[32592]: info: [1774574913401] CoreMusicLibrary::Adding element Webradio Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 10:28:33 volumio44 volumio[32592]: info: Initializing BBC Radios Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: Creating Spotify config file Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: JP_Radio::onStart: start... Mar 27 10:28:33 volumio44 volumio[32592]: info: JP_Radio::JpRadio.#setupRoutes Mar 27 10:28:33 volumio44 volumio[32592]: info: JP_Radio::JpRadio.start Mar 27 10:28:33 volumio44 volumio[32592]: info: JP_Radio::JpRadio.#init start... Mar 27 10:28:33 volumio44 volumio[32592]: info: JP_Radio::Radiko.init Mar 27 10:28:33 volumio44 volumio[32592]: info: JP_Radio::Attempting login Mar 27 10:28:33 volumio44 volumio[32592]: info: JP_Radio::Radiko.checkLogin Mar 27 10:28:33 volumio44 volumio[32592]: info: Volumio Calling Home Mar 27 10:28:33 volumio44 systemd[1]: mpd.service: Deactivated successfully. Mar 27 10:28:33 volumio44 systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 27 10:28:33 volumio44 systemd[1]: mpd.service: Consumed 1min 35.665s CPU time. Mar 27 10:28:33 volumio44 systemd[1]: mpd.socket: Deactivated successfully. Mar 27 10:28:33 volumio44 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 27 10:28:33 volumio44 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 27 10:28:33 volumio44 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 27 10:28:33 volumio44 systemd[1]: Starting mpd.service - Music Player Daemon... Mar 27 10:28:33 volumio44 volumio[32592]: info: MPD Permissions set Mar 27 10:28:33 volumio44 volumio[32592]: info: MPD Permissions set Mar 27 10:28:33 volumio44 volumio[32592]: info: VolumeController:: Volume=91 Mute =false Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreStateMachine::pushState Mar 27 10:28:33 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:33 volumio44 volumio[32592]: info: Spotify config file written Mar 27 10:28:33 volumio44 sudo[313]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 27 10:28:33 volumio44 sudo[313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 27 10:28:33 volumio44 sudo[315]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 10:28:33 volumio44 volumio[32592]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 27 10:28:33 volumio44 sudo[315]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 sudo[313]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:33 volumio44 volumio[32592]: info: No need to fix Spotify hosts Mar 27 10:28:33 volumio44 systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Mar 27 10:28:33 volumio44 volumio[32592]: info: Starting Shairport Sync Mar 27 10:28:33 volumio44 systemd[1]: go-librespot-daemon.service: Deactivated successfully. Mar 27 10:28:33 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:33 volumio44 volumio[32592]: info: Starting Shairport Sync Mar 27 10:28:33 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:33 volumio44 volumio[32592]: info: Starting Shairport Sync Mar 27 10:28:33 volumio44 go-librespot[330]: go-librespot daemon starting... Mar 27 10:28:33 volumio44 sudo[315]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:33 volumio44 sudo[331]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 10:28:33 volumio44 sudo[331]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 sudo[338]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 10:28:33 volumio44 go-librespot[334]: time="2026-03-27T10:28:33+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:33 volumio44 go-librespot[334]: time="2026-03-27T10:28:33+09:00" level=debug msg="app state loaded" Mar 27 10:28:33 volumio44 sudo[338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:33 volumio44 sudo[333]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 10:28:33 volumio44 sudo[333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:34 volumio44 go-librespot[334]: time="2026-03-27T10:28:34+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:34 volumio44 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 27 10:28:34 volumio44 systemd[1]: shairport-sync.service: Deactivated successfully. Mar 27 10:28:34 volumio44 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 27 10:28:34 volumio44 systemd[1]: shairport-sync.service: Consumed 27.729s CPU time. Mar 27 10:28:34 volumio44 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 27 10:28:34 volumio44 sudo[333]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:34 volumio44 sudo[331]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:34 volumio44 sudo[338]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:34 volumio44 volumio[32592]: info: Shairport-Sync Started Mar 27 10:28:34 volumio44 volumio[32592]: Error adding Membership: Error: addMembership EINVAL Mar 27 10:28:34 volumio44 volumio[32592]: info: Shairport-Sync Started Mar 27 10:28:34 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:34.062+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:28:34 volumio44 volumio[32592]: info: Shairport-Sync Started Mar 27 10:28:35 volumio44 mpd[320]: 2026-03-27T10:28:35 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 27 10:28:35 volumio44 systemd[1]: Started mpd.service - Music Player Daemon. Mar 27 10:28:35 volumio44 sudo[32740]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:35 volumio44 sudo[32752]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:35 volumio44 volumio[32592]: error: MPD error: The expression evaluated to a falsy value: Mar 27 10:28:35 volumio44 volumio[32592]: assert.ok(self.idling) Mar 27 10:28:35 volumio44 volumio[32592]: error: The expression evaluated to a falsy value: Mar 27 10:28:35 volumio44 volumio[32592]: assert.ok(self.idling) Mar 27 10:28:35 volumio44 volumio[32592]: info: MPD running with PID320 Mar 27 10:28:35 volumio44 volumio[32592]: ,establishing connection Mar 27 10:28:35 volumio44 volumio[32592]: error: updateQueue error: null Mar 27 10:28:35 volumio44 volumio[32592]: error: updateQueue error: null Mar 27 10:28:36 volumio44 volumio[32592]: info: go-librespot daemon successfully initialized Mar 27 10:28:37 volumio44 sudo[391]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 10:28:37 volumio44 sudo[391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:37 volumio44 sudo[393]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 10:28:37 volumio44 sudo[393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:37 volumio44 sudo[391]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:37 volumio44 sudo[393]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:37 volumio44 sudo[395]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 27 10:28:37 volumio44 sudo[395]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:37 volumio44 sudo[395]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:37 volumio44 volumio[32592]: info: Upmpdcli Daemon Started Mar 27 10:28:39 volumio44 volumio[32592]: info: Initializing connection to go-librespot Websocket Mar 27 10:28:40 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-DISCONNECTED bssid=f8:b7:97:73:a3:22 reason=0 locally_generated=1 Mar 27 10:28:40 volumio44 dhcpcd[748]: wlan0: carrier lost Mar 27 10:28:40 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Mar 27 10:28:40 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=JP Mar 27 10:28:40 volumio44 avahi-daemon[1350]: Withdrawing address record for 192.168.10.101 on wlan0. Mar 27 10:28:40 volumio44 avahi-daemon[1350]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.10.101. Mar 27 10:28:40 volumio44 avahi-daemon[1350]: Interface wlan0.IPv4 no longer relevant for mDNS. Mar 27 10:28:40 volumio44 dhcpcd[748]: wlan0: deleting route to 192.168.10.0/24 Mar 27 10:28:40 volumio44 dhcpcd[748]: wlan0: deleting default route via 192.168.10.1 Mar 27 10:28:40 volumio44 volumio[32592]: info: Discovery: A device disappeared from network Mar 27 10:28:40 volumio44 systemd[1]: Stopped target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 27 10:28:40 volumio44 systemd[1]: Stopping ip-changed@wlan0.target - IP Address changed on wlan0... Mar 27 10:28:40 volumio44 systemd[1]: welcome.service: Deactivated successfully. Mar 27 10:28:40 volumio44 systemd[1]: Stopped welcome.service - Show a welcome message on console. Mar 27 10:28:40 volumio44 systemd[1]: Stopping welcome.service - Show a welcome message on console... Mar 27 10:28:41 volumio44 systemd[1]: Starting welcome.service - Show a welcome message on console... Mar 27 10:28:41 volumio44 welcome[427]: Resolved ip:[0] Mar 27 10:28:41 volumio44 systemd[1]: Finished welcome.service - Show a welcome message on console. Mar 27 10:28:41 volumio44 systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 27 10:28:41 volumio44 volumio[32592]: info: Received Get System Info Mar 27 10:28:41 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:28:41 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:28:41 volumio44 volumio[32592]: info: Discovery: Getting this device information Mar 27 10:28:41 volumio44 volumio[32592]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:41 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:41 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:28:41 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:28:41 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:28:42 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:42.187+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:28:42 volumio44 ntpd[1048]: IO: Deleting interface #4 wlan0, 192.168.10.101#123, interface stats: received=0, sent=2, dropped=0, active_time=291 secs Mar 27 10:28:42 volumio44 ntpd[1048]: PROTO: 138.3.209.153 unlink local addr 192.168.10.101 -> Mar 27 10:28:42 volumio44 ntpd[1048]: PROTO: 129.250.35.251 unlink local addr 192.168.10.101 -> Mar 27 10:28:42 volumio44 ntpd[1048]: PROTO: 85.121.122.62 unlink local addr 192.168.10.101 -> Mar 27 10:28:42 volumio44 ntpd[1048]: PROTO: 160.16.113.133 unlink local addr 192.168.10.101 -> Mar 27 10:28:42 volumio44 ntpd[1048]: PROTO: 172.105.192.74 unlink local addr 192.168.10.101 -> Mar 27 10:28:42 volumio44 ntpd[1048]: PROTO: 142.91.108.61 unlink local addr 192.168.10.101 -> Mar 27 10:28:42 volumio44 ntpd[1048]: PROTO: 167.179.119.205 unlink local addr 192.168.10.101 -> Mar 27 10:28:42 volumio44 volumio[32592]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo ENOTFOUND oauth-performer.prod.vlmapi.io Mar 27 10:28:42 volumio44 volumio[32592]: error: JP_Radio::premium account login check error: getaddrinfo EBUSY radiko.jp getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574922616,"lookup":1774574922616,"phases":{"dns":8800,"total":8804,"wait":4},"socket":1774574913816,"start":1774574913812}} Mar 27 10:28:42 volumio44 volumio[32592]: info: JP_Radio::Radiko.login Mar 27 10:28:42 volumio44 volumio[32592]: info: Discovery: adding d53f94ae-f88e-489a-b898-760151f1ab34 Mar 27 10:28:42 volumio44 volumio[32592]: info: Discovery: Found device Volumio44 Mar 27 10:28:42 volumio44 volumio[32592]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:42 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:42 volumio44 volumio[32592]: info: Discovery: this is already registered, d53f94ae-f88e-489a-b898-760151f1ab34 Mar 27 10:28:42 volumio44 volumio[32592]: info: Discovery: Found device Volumio44 Mar 27 10:28:42 volumio44 volumio[32592]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:42 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:42 volumio44 volumio[32592]: error: JP_Radio::Login failed getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574922649,"lookup":1774574922649,"phases":{"dns":13,"total":14,"wait":1},"socket":1774574922636,"start":1774574922635}} Mar 27 10:28:42 volumio44 volumio[32592]: error: JP_Radio::Failed to start appRadio getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574922649,"lookup":1774574922649,"phases":{"dns":13,"total":14,"wait":1},"socket":1774574922636,"start":1774574922635}} Mar 27 10:28:42 volumio44 volumio[32592]: error: JP_Radio::Failed to start appRadio getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574922649,"lookup":1774574922649,"phases":{"dns":13,"total":14,"wait":1},"socket":1774574922636,"start":1774574922635}} Mar 27 10:28:42 volumio44 volumio[32592]: info: Completed starting Core Plugins Mar 27 10:28:42 volumio44 volumio[32592]: info: ------------------------------------------- Mar 27 10:28:42 volumio44 volumio[32592]: info: ----- MyVolumio plugins startup ---- Mar 27 10:28:42 volumio44 volumio[32592]: info: ------------------------------------------- Mar 27 10:28:42 volumio44 volumio[32592]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 27 10:28:42 volumio44 go-librespot[334]: time="2026-03-27T10:28:42+09:00" level=debug msg="new websocket client" Mar 27 10:28:42 volumio44 volumio[32592]: info: Connection to go-librespot Websocket established Mar 27 10:28:42 volumio44 volumio[32592]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:42 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:43 volumio44 go-librespot[334]: time="2026-03-27T10:28:43+09: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 27 10:28:43 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:43 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:28:43 volumio44 volumio[32592]: info: Connection to go-librespot Websocket closed Mar 27 10:28:43 volumio44 wpa_supplicant[1188]: wlan0: Trying to associate with f8:b7:97:73:a3:23 (SSID='aterm-9f10fa-a' freq=5500 MHz) Mar 27 10:28:43 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Mar 27 10:28:44 volumio44 volumio[32592]: info: Received Get System Info Mar 27 10:28:44 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:28:44 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:28:44 volumio44 volumio[32592]: info: Discovery: Getting this device information Mar 27 10:28:44 volumio44 volumio[32592]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:44 volumio44 volumio[32592]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:44 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:28:44 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:28:44 volumio44 volumio[32592]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:28:44 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:44.835+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:28:45 volumio44 nmbd[1094]: [2026/03/27 10:28:45.117586, 0] ../../source3/nmbd/nmbd.c:359(reload_interfaces) Mar 27 10:28:45 volumio44 nmbd[1094]: reload_interfaces: No subnets to listen to. Waiting.. Mar 27 10:28:45 volumio44 volumio[32592]: info: Getting Spotify volume Mar 27 10:28:45 volumio44 volumio[32592]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 10:28:45 volumio44 volumio[32592]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:28:45 volumio44 volumio[32592]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 27 10:28:45 volumio44 volumio[32592]: errno: -111, Mar 27 10:28:45 volumio44 volumio[32592]: code: 'ECONNREFUSED', Mar 27 10:28:45 volumio44 volumio[32592]: syscall: 'connect', Mar 27 10:28:45 volumio44 volumio[32592]: address: '127.0.0.1', Mar 27 10:28:45 volumio44 volumio[32592]: port: 9879, Mar 27 10:28:45 volumio44 volumio[32592]: response: undefined Mar 27 10:28:45 volumio44 volumio[32592]: } Mar 27 10:28:45 volumio44 volumio[32592]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 10:28:46 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 27 10:28:46 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:46 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:46 volumio44 go-librespot[445]: go-librespot daemon starting... Mar 27 10:28:46 volumio44 sudo[448]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-27 10:27' Mar 27 10:28:46 volumio44 sudo[448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:46 volumio44 go-librespot[449]: time="2026-03-27T10:28:46+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:46 volumio44 go-librespot[449]: time="2026-03-27T10:28:46+09:00" level=debug msg="app state loaded" Mar 27 10:28:46 volumio44 go-librespot[449]: time="2026-03-27T10:28:46+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:46 volumio44 go-librespot[449]: time="2026-03-27T10:28:46+09: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 27 10:28:46 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:46 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:28:46 volumio44 sudo[448]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:46 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:46.217+09:00 level=ERROR msg="failed reading message" error="websocket: close 1006 (abnormal closure): unexpected EOF" Mar 27 10:28:46 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:46] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Mar 27 10:28:46 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:46] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Mar 27 10:28:46 volumio44 systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:46 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:46.225+09:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 27 10:28:46 volumio44 systemd[1]: volumio.service: Failed with result 'exit-code'. Mar 27 10:28:46 volumio44 systemd[1]: volumio.service: Consumed 16.758s CPU time. Mar 27 10:28:46 volumio44 systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 27 10:28:46 volumio44 systemd[1]: dynamicswap.service: Deactivated successfully. Mar 27 10:28:46 volumio44 systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2. Mar 27 10:28:46 volumio44 systemd[1]: Started dynamicswap.service - dynamicswap service. Mar 27 10:28:46 volumio44 systemd[1]: Stopped volumio.service - Volumio Backend Module. Mar 27 10:28:46 volumio44 systemd[1]: volumio.service: Consumed 16.758s CPU time. Mar 27 10:28:46 volumio44 systemd[1]: Started volumio.service - Volumio Backend Module. Mar 27 10:28:46 volumio44 systemd[1]: dynamicswap.service: Deactivated successfully. Mar 27 10:28:46 volumio44 wpa_supplicant[1188]: wlan0: Trying to associate with f8:b7:97:73:a3:23 (SSID='aterm-9f10fa-a' freq=5500 MHz) Mar 27 10:28:47 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:47.227+09:00 level=WARN msg="reconnection attempt failed" error="dial tcp 127.0.0.1:3000: connect: connection refused" Mar 27 10:28:47 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Mar 27 10:28:47 volumio44 wpa_supplicant[1188]: BSSID f8:b7:97:73:a3:23 ignore list count incremented to 2, ignoring for 10 seconds Mar 27 10:28:47 volumio44 volumio[482]: info: ------------------------------------------- Mar 27 10:28:47 volumio44 volumio[482]: info: ----- Volumio3 ---- Mar 27 10:28:47 volumio44 volumio[482]: info: ------------------------------------------- Mar 27 10:28:47 volumio44 volumio[482]: info: ----- System startup ---- Mar 27 10:28:47 volumio44 volumio[482]: info: ------------------------------------------- Mar 27 10:28:48 volumio44 volumio[482]: info: MYVOLUMIO Environment detected Mar 27 10:28:48 volumio44 volumio[482]: info: Plugin folders cleanup Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning into folder /volumio/app/plugins/ Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning category audio_interface Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning category miscellanea Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning category music_service Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning category plugins.json Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning category system_controller Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning category user_interface Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning into folder /data/plugins/ Mar 27 10:28:48 volumio44 volumio[482]: info: Scanning category music_service Mar 27 10:28:48 volumio44 volumio[482]: info: Plugin folders cleanup completed Mar 27 10:28:48 volumio44 volumio[482]: info: ------------------------------------------- Mar 27 10:28:48 volumio44 volumio[482]: info: ----- Core plugins startup ---- Mar 27 10:28:48 volumio44 volumio[482]: info: ------------------------------------------- Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugins from folder /volumio/app/plugins/ Mar 27 10:28:48 volumio44 volumio[482]: info: Adding plugin upnp to MyMusic Plugins Mar 27 10:28:48 volumio44 volumio[482]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 27 10:28:48 volumio44 volumio[482]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugins from folder /data/plugins/ Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "system"... Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "appearance"... Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "network"... Mar 27 10:28:48 volumio44 volumio[482]: info: Refreshing Cached IP Addresses Mar 27 10:28:48 volumio44 sudo[510]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 10:28:48 volumio44 sudo[510]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:48 volumio44 sudo[510]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:48 volumio44 sudo[512]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 10:28:48 volumio44 sudo[512]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:48 volumio44 sudo[512]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "services"... Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "volumio5onboarding"... Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "alsa_controller"... Mar 27 10:28:48 volumio44 sudo[521]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 27 10:28:48 volumio44 sudo[521]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:48 volumio44 sudo[521]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:48 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "wizard"... Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "networkfs"... Mar 27 10:28:48 volumio44 volumio[482]: info: Starting Udev Watcher for removable devices Mar 27 10:28:48 volumio44 volumio[482]: info: Ignoring mount for partition: boot Mar 27 10:28:48 volumio44 volumio[482]: info: Ignoring mount for partition: volumio Mar 27 10:28:48 volumio44 volumio[482]: info: Ignoring mount for partition: volumio_data Mar 27 10:28:48 volumio44 volumio[482]: info: Mounting Device 3266-3164 Mar 27 10:28:48 volumio44 sudo[558]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/3266-3164 -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 27 10:28:48 volumio44 sudo[558]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:48 volumio44 sudo[558]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:48 volumio44 volumio[482]: mount: /media/3266-3164: /dev/sda1 already mounted on /media/3266-3164. Mar 27 10:28:48 volumio44 volumio[482]: dmesg(1) may have more information after failed mount system call. Mar 27 10:28:48 volumio44 volumio[482]: error: Failed to mount 3266-3164: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/3266-3164" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Mar 27 10:28:48 volumio44 volumio[482]: mount: /media/3266-3164: /dev/sda1 already mounted on /media/3266-3164. Mar 27 10:28:48 volumio44 volumio[482]: dmesg(1) may have more information after failed mount system call. Mar 27 10:28:48 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "volumio_command_line_client"... Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "upnp"... Mar 27 10:28:48 volumio44 volumio[482]: info: [1774574928936] Starting Upmpd Daemon Mar 27 10:28:48 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "my_music"... Mar 27 10:28:48 volumio44 volumio[482]: info: Loading plugin "mpd"... Mar 27 10:28:49 volumio44 volumio[482]: info: Loading plugin "upnp_browser"... Mar 27 10:28:49 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 27 10:28:49 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:49 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:49 volumio44 go-librespot[560]: go-librespot daemon starting... Mar 27 10:28:49 volumio44 go-librespot[561]: time="2026-03-27T10:28:49+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:49 volumio44 go-librespot[561]: time="2026-03-27T10:28:49+09:00" level=debug msg="app state loaded" Mar 27 10:28:49 volumio44 go-librespot[561]: time="2026-03-27T10:28:49+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:49 volumio44 go-librespot[561]: time="2026-03-27T10:28:49+09: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 27 10:28:49 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:49 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:28:49 volumio44 volumio[482]: info: Starting UPNP Browser Mar 27 10:28:49 volumio44 volumio[482]: info: Loading plugin "alarm-clock"... Mar 27 10:28:49 volumio44 volumio[482]: info: Loading plugin "airplay_emulation"... Mar 27 10:28:50 volumio44 volumio[482]: info: Starting Shairport Sync Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "last_100"... Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "webradio"... Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "i2s_dacs"... Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "volumiodiscovery"... Mar 27 10:28:50 volumio44 volumio[482]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:50 volumio44 volumio[482]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:50 volumio44 volumio[482]: *** WARNING *** For more information see Mar 27 10:28:50 volumio44 volumio[482]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:50 volumio44 volumio[482]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:50 volumio44 volumio[482]: *** WARNING *** For more information see Mar 27 10:28:50 volumio44 node[482]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:50 volumio44 node[482]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:50 volumio44 node[482]: *** WARNING *** For more information see Mar 27 10:28:50 volumio44 node[482]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 27 10:28:50 volumio44 node[482]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 27 10:28:50 volumio44 node[482]: *** WARNING *** For more information see Mar 27 10:28:50 volumio44 volumio[482]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 27 10:28:50 volumio44 volumio[482]: info: Discovery: Started advertising with name: Volumio44 Mar 27 10:28:50 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "spop"... Mar 27 10:28:50 volumio44 volumio[482]: info: Plugin ytmusic is not enabled Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "outputs"... Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "albumart"... Mar 27 10:28:50 volumio44 volumio[482]: info: Plugin example_plugin is not enabled Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "inputs"... Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "updater_comm"... Mar 27 10:28:50 volumio44 volumio[482]: info: Plugin mpdemulation is not enabled Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "rest_api"... Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "websocket"... Mar 27 10:28:50 volumio44 volumio[482]: info: Starting Socket.io Server version 1.7.4 Mar 27 10:28:50 volumio44 volumio[482]: info: Loading plugin "jp_radio"... Mar 27 10:28:50 volumio44 wpa_supplicant[1188]: wlan0: Trying to associate with f8:b7:97:73:a3:22 (SSID='aterm-9f10fa-g' freq=2462 MHz) Mar 27 10:28:50 volumio44 volumio[571]: Forking 3 albumart workers Mar 27 10:28:51 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:51] [connect] Successful connection Mar 27 10:28:51 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Mar 27 10:28:51 volumio44 wpa_supplicant[1188]: BSSID f8:b7:97:73:a3:22 ignore list count incremented to 2, ignoring for 10 seconds Mar 27 10:28:51 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=2 ssid="aterm-9f10fa-g" auth_failures=1 duration=10 reason=CONN_FAILED Mar 27 10:28:51 volumio44 volumio[581]: Starting albumart workers Mar 27 10:28:51 volumio44 volumio[583]: Starting albumart workers Mar 27 10:28:51 volumio44 volumio[582]: Starting albumart workers Mar 27 10:28:52 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 27 10:28:52 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:52 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:52 volumio44 go-librespot[632]: go-librespot daemon starting... Mar 27 10:28:52 volumio44 go-librespot[633]: time="2026-03-27T10:28:52+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:52 volumio44 go-librespot[633]: time="2026-03-27T10:28:52+09:00" level=debug msg="app state loaded" Mar 27 10:28:52 volumio44 go-librespot[633]: time="2026-03-27T10:28:52+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:52 volumio44 go-librespot[633]: time="2026-03-27T10:28:52+09: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 27 10:28:52 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:52 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:28:52 volumio44 volumio[482]: info: JP_Radio::onVolumioStart Mar 27 10:28:52 volumio44 volumio[482]: info: Loading i18n strings for locale ja Mar 27 10:28:52 volumio44 volumio[482]: Updating browse sources language Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::initPlayerControls Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 10:28:52 volumio44 volumio[482]: Express server listening on port 3000 Mar 27 10:28:52 volumio44 volumio[482]: [Metrics] WebUI: 5s 578.47ms Mar 27 10:28:53 volumio44 volumio[482]: info: CoreStateMachine::resetVolumioState Mar 27 10:28:53 volumio44 volumio[482]: info: CoreStateMachine::getcurrentVolume Mar 27 10:28:53 volumio44 volumio[482]: info: CoreCommandRouter::volumioRetrievevolume Mar 27 10:28:53 volumio44 volumio[482]: info: Volumio Network Manager: Network status updated: 0 Mar 27 10:28:53 volumio44 volumio[482]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Mar 27 10:28:53 volumio44 volumio[482]: wlan0 Interface doesn't support scanning : Device or resource busy Mar 27 10:28:53 volumio44 volumio[482]: info: Cannot use regular scanning, forcing with ap-force Mar 27 10:28:53 volumio44 sudo[647]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Mar 27 10:28:53 volumio44 sudo[647]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:55 volumio44 sudo[647]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:55 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 27 10:28:55 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:55 volumio44 volumio[482]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 27 10:28:55 volumio44 volumio[482]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 1 Mar 27 10:28:55 volumio44 volumio[482]: info: Received Get System Info Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:28:55 volumio44 volumio[482]: info: Discovery: Getting this device information Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:55 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:55 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:28:55 volumio44 go-librespot[649]: go-librespot daemon starting... Mar 27 10:28:55 volumio44 volumio[482]: info: Received Get System Info Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:28:55 volumio44 volumio[482]: info: Discovery: Getting this device information Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:55 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:28:55 volumio44 volumio-remote-updater[699]: [2026-03-27 10:28:55] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774574931 101 Mar 27 10:28:55 volumio44 volumio[482]: 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: 2 Mar 27 10:28:55 volumio44 go-librespot[651]: time="2026-03-27T10:28:55+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:55 volumio44 go-librespot[651]: time="2026-03-27T10:28:55+09:00" level=debug msg="app state loaded" Mar 27 10:28:55 volumio44 go-librespot[651]: time="2026-03-27T10:28:55+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:55 volumio44 go-librespot[651]: time="2026-03-27T10:28:55+09: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 27 10:28:55 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:55 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:55 volumio44 volumio[482]: info: Reloading queue from file Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:28:55 volumio44 volumio[482]: info: VolumeController:: Volume=91 Mute =false Mar 27 10:28:55 volumio44 volumio[482]: info: CoreStateMachine::pushState Mar 27 10:28:55 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:55 volumio44 volumio[482]: info: CoreStateMachine::updateTrackBlock Mar 27 10:28:55 volumio44 volumio[482]: info: CorePlayQueue::getTrackBlock Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioRetrievevolume Mar 27 10:28:55 volumio44 volumio[482]: info: CoreStateMachine::setRepeat null single undefined Mar 27 10:28:55 volumio44 volumio[482]: info: CoreStateMachine::pushState Mar 27 10:28:55 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:55 volumio44 volumio[482]: info: CoreStateMachine::setRandom null Mar 27 10:28:55 volumio44 volumio[482]: info: CoreStateMachine::pushState Mar 27 10:28:55 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:55 volumio44 volumio[482]: info: Setting Device type: Raspberry PI Mar 27 10:28:55 volumio44 volumio[482]: info: Completed loading Core Plugins Mar 27 10:28:55 volumio44 volumio[482]: info: Preparing to generate the ALSA configuration file Mar 27 10:28:55 volumio44 volumio[482]: info: Asound.conf file unchanged, so no further update is needed Mar 27 10:28:55 volumio44 volumio[482]: info: Output device has changed, restarting MPD Mar 27 10:28:55 volumio44 volumio[482]: info: Output device has changed, restarting Shairport Sync Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:55 volumio44 sudo[669]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 27 10:28:55 volumio44 sudo[669]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:55 volumio44 sudo[671]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 27 10:28:55 volumio44 sudo[671]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:55 volumio44 sudo[669]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:55 volumio44 volumio[482]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 27 10:28:55 volumio44 volumio[482]: info: ___________ START PLUGINS ___________ Mar 27 10:28:55 volumio44 volumio[482]: info: ControllerMpd::onStart: Initializing MPD Mar 27 10:28:55 volumio44 volumio[482]: info: Creating MPD Configuration file Mar 27 10:28:55 volumio44 sudo[679]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Mar 27 10:28:55 volumio44 sudo[679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 10:28:55 volumio44 volumio[482]: info: [1774574935883] CoreMusicLibrary::Adding element DLNAサーバー Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:55 volumio44 systemd[1]: Stopping mpd.service - Music Player Daemon... Mar 27 10:28:55 volumio44 volumio[482]: info: UPNP Browser: Client initialized successfully Mar 27 10:28:55 volumio44 sudo[685]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 27 10:28:55 volumio44 sudo[685]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:55 volumio44 sudo[681]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 27 10:28:55 volumio44 sudo[681]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:55 volumio44 sudo[681]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:55 volumio44 volumio[482]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:55 volumio44 sudo[679]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:55 volumio44 systemd[1]: mpd.service: Deactivated successfully. Mar 27 10:28:55 volumio44 systemd[1]: Stopped mpd.service - Music Player Daemon. Mar 27 10:28:55 volumio44 systemd[1]: mpd.service: Consumed 1.649s CPU time. Mar 27 10:28:55 volumio44 systemd[1]: mpd.socket: Deactivated successfully. Mar 27 10:28:55 volumio44 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Mar 27 10:28:55 volumio44 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Mar 27 10:28:55 volumio44 volumio[482]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 10:28:55 volumio44 volumio[482]: info: [1774574935952] CoreMusicLibrary::Adding element Last_100 Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 27 10:28:55 volumio44 volumio[482]: info: [1774574935955] CoreMusicLibrary::Adding element Webradio Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 10:28:55 volumio44 volumio[482]: info: Initializing BBC Radios Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 10:28:55 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:55 volumio44 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Mar 27 10:28:56 volumio44 systemd[1]: Starting mpd.service - Music Player Daemon... Mar 27 10:28:56 volumio44 volumio[482]: info: Creating Spotify config file Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 sudo[714]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 27 10:28:56 volumio44 sudo[714]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Mar 27 10:28:56 volumio44 sudo[714]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::onStart: start... Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::JpRadio.#setupRoutes Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::JpRadio.start Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::JpRadio.#init start... Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::Radiko.init Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::Attempting login Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::Radiko.checkLogin Mar 27 10:28:56 volumio44 volumio[482]: info: Volumio Calling Home Mar 27 10:28:56 volumio44 volumio[482]: Unhandled rejection Error: No sockets available, cannot start. Mar 27 10:28:56 volumio44 volumio[482]: at SSDP._createSockets (/volumio/node_modules/node-ssdp/lib/index.js:186:11) Mar 27 10:28:56 volumio44 volumio[482]: at SSDP._start (/volumio/node_modules/node-ssdp/lib/index.js:229:10) Mar 27 10:28:56 volumio44 volumio[482]: at /volumio/node_modules/node-ssdp/lib/client.js:60:10 Mar 27 10:28:56 volumio44 volumio[482]: at Promise._execute (/volumio/node_modules/bluebird/js/release/debuggability.js:384:9) Mar 27 10:28:56 volumio44 volumio[482]: at Promise._resolveFromExecutor (/volumio/node_modules/bluebird/js/release/promise.js:518:18) Mar 27 10:28:56 volumio44 volumio[482]: at new Promise (/volumio/node_modules/bluebird/js/release/promise.js:103:10) Mar 27 10:28:56 volumio44 volumio[482]: at SsdpClient.start (/volumio/node_modules/node-ssdp/lib/client.js:54:10) Mar 27 10:28:56 volumio44 volumio[482]: at SsdpClient.search (/volumio/node_modules/node-ssdp/lib/client.js:82:17) Mar 27 10:28:56 volumio44 volumio[482]: at ControllerUPNPBrowser.onStart (/volumio/app/plugins/music_service/upnp_browser/index.js:156:14) Mar 27 10:28:56 volumio44 volumio[482]: at PluginManager.startCorePlugin (/volumio/app/pluginmanager.js:398:24) Mar 27 10:28:56 volumio44 volumio[482]: at HashMap. (/volumio/app/pluginmanager.js:496:31) Mar 27 10:28:56 volumio44 volumio[482]: at HashMap.forEach (/volumio/node_modules/hashmap/hashmap.js:171:10) Mar 27 10:28:56 volumio44 volumio[482]: at proto. [as forEach] (/volumio/node_modules/hashmap/hashmap.js:201:7) Mar 27 10:28:56 volumio44 volumio[482]: at PluginManager.startCorePlugins (/volumio/app/pluginmanager.js:495:20) Mar 27 10:28:56 volumio44 volumio[482]: at Promise._successFn (/volumio/app/pluginmanager.js:142:29) Mar 27 10:28:56 volumio44 volumio[482]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 27 10:28:56 volumio44 volumio[482]: info: Discovery: adding d53f94ae-f88e-489a-b898-760151f1ab34 Mar 27 10:28:56 volumio44 volumio[482]: info: Discovery: Found device Volumio44 Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:56 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:56 volumio44 volumio[482]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo EBUSY oauth-performer.prod.vlmapi.io Mar 27 10:28:56 volumio44 volumio[482]: error: JP_Radio::premium account login check error: getaddrinfo EBUSY radiko.jp getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574936410,"lookup":1774574936410,"phases":{"dns":35,"total":40,"wait":5},"socket":1774574936375,"start":1774574936370}} Mar 27 10:28:56 volumio44 volumio[482]: info: JP_Radio::Radiko.login Mar 27 10:28:56 volumio44 volumio[482]: info: Received Get System Info Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:28:56 volumio44 volumio[482]: info: Discovery: Getting this device information Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:56 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:28:56 volumio44 volumio[482]: info: MPD Permissions set Mar 27 10:28:56 volumio44 volumio[482]: info: MPD Permissions set Mar 27 10:28:56 volumio44 volumio[482]: info: VolumeController:: Volume=91 Mute =false Mar 27 10:28:56 volumio44 volumio[482]: info: CoreStateMachine::pushState Mar 27 10:28:56 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::volumioPushState Mar 27 10:28:56 volumio44 volumio[482]: error: JP_Radio::Login failed getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574936473,"lookup":1774574936472,"phases":{"dns":39,"total":42,"wait":2},"socket":1774574936433,"start":1774574936431}} Mar 27 10:28:56 volumio44 volumio[482]: error: JP_Radio::Failed to start appRadio getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574936473,"lookup":1774574936472,"phases":{"dns":39,"total":42,"wait":2},"socket":1774574936433,"start":1774574936431}} Mar 27 10:28:56 volumio44 volumio[482]: error: JP_Radio::Failed to start appRadio getaddrinfo EBUSY radiko.jp {"code":"EBUSY","name":"RequestError","stack":"RequestError: getaddrinfo EBUSY radiko.jp\n at ClientRequest. (/data/plugins/music_service/jp_radio/node_modules/got/dist/source/core/index.js:970:111)\n at Object.onceWrapper (node:events:629:26)\n at ClientRequest.emit (node:events:526:35)\n at origin.emit (/data/plugins/music_service/jp_radio/node_modules/@szmarczak/http-timer/dist/source/index.js:43:20)\n at TLSSocket.socketErrorListener (node:_http_client:495:9)\n at TLSSocket.emit (node:events:514:28)\n at emitErrorNT (node:internal/streams/destroy:151:8)\n at emitErrorCloseNT (node:internal/streams/destroy:116:3)\n at process.processTicksAndRejections (node:internal/process/task_queues:82:21)\n at GetAddrInfoReqWrap.onlookupall [as oncomplete] (node:dns:118:26)","timings":{"error":1774574936473,"lookup":1774574936472,"phases":{"dns":39,"total":42,"wait":2},"socket":1774574936433,"start":1774574936431}} Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:28:56 volumio44 volumio[482]: info: Spotify config file written Mar 27 10:28:56 volumio44 sudo[721]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 27 10:28:56 volumio44 sudo[721]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:56 volumio44 volumio[482]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:56 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:28:56 volumio44 volumio[482]: info: No need to fix Spotify hosts Mar 27 10:28:56 volumio44 volumio[482]: info: Starting Shairport Sync Mar 27 10:28:56 volumio44 volumio[482]: info: Starting Shairport Sync Mar 27 10:28:56 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:56 volumio44 go-librespot[729]: go-librespot daemon starting... Mar 27 10:28:56 volumio44 volumio[482]: info: Starting Shairport Sync Mar 27 10:28:56 volumio44 sudo[721]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:56 volumio44 sudo[736]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 10:28:56 volumio44 go-librespot[738]: time="2026-03-27T10:28:56+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:56 volumio44 go-librespot[738]: time="2026-03-27T10:28:56+09:00" level=debug msg="app state loaded" Mar 27 10:28:56 volumio44 sudo[739]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 10:28:56 volumio44 sudo[739]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:56 volumio44 sudo[736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:56 volumio44 go-librespot[738]: time="2026-03-27T10:28:56+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:56 volumio44 go-librespot[738]: time="2026-03-27T10:28:56+09: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 27 10:28:56 volumio44 sudo[752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 27 10:28:56 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:56 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:28:56 volumio44 sudo[752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:56 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:56 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:56 volumio44 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Mar 27 10:28:56 volumio44 systemd[1]: shairport-sync.service: Deactivated successfully. Mar 27 10:28:56 volumio44 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 27 10:28:56 volumio44 systemd[1]: shairport-sync.service: Consumed 1.713s CPU time. Mar 27 10:28:56 volumio44 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Mar 27 10:28:56 volumio44 sudo[752]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:56 volumio44 sudo[736]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:56 volumio44 sudo[739]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:56 volumio44 volumio[482]: info: Shairport-Sync Started Mar 27 10:28:56 volumio44 volumio[482]: Error adding Membership: Error: addMembership EINVAL Mar 27 10:28:56 volumio44 volumio[482]: info: Shairport-Sync Started Mar 27 10:28:56 volumio44 volumio[482]: info: Shairport-Sync Started Mar 27 10:28:57 volumio44 mpd[716]: 2026-03-27T10:28:57 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 27 10:28:57 volumio44 systemd[1]: Started mpd.service - Music Player Daemon. Mar 27 10:28:57 volumio44 sudo[685]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:57 volumio44 sudo[671]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:57 volumio44 volumio[482]: info: Completed starting Core Plugins Mar 27 10:28:57 volumio44 volumio[482]: info: ------------------------------------------- Mar 27 10:28:57 volumio44 volumio[482]: info: ----- MyVolumio plugins startup ---- Mar 27 10:28:57 volumio44 volumio[482]: info: ------------------------------------------- Mar 27 10:28:57 volumio44 volumio[482]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 27 10:28:57 volumio44 volumio[482]: error: updateQueue error: null Mar 27 10:28:57 volumio44 volumio[482]: error: updateQueue error: null Mar 27 10:28:57 volumio44 volumio[482]: info: MPD running with PID716 Mar 27 10:28:57 volumio44 volumio[482]: ,establishing connection Mar 27 10:28:57 volumio44 volumio[482]: error: updateQueue error: null Mar 27 10:28:58 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:28:58.571+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:28:58 volumio44 wpa_supplicant[1188]: wlan0: Trying to associate with f8:b7:97:73:a3:23 (SSID='aterm-9f10fa-a' freq=5500 MHz) Mar 27 10:28:58 volumio44 sudo[795]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 27 10:28:58 volumio44 sudo[795]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:58 volumio44 sudo[797]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 27 10:28:58 volumio44 sudo[797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:58 volumio44 sudo[795]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:58 volumio44 sudo[797]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:58 volumio44 sudo[799]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 27 10:28:58 volumio44 sudo[799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 10:28:59 volumio44 sudo[799]: pam_unix(sudo:session): session closed for user root Mar 27 10:28:59 volumio44 volumio[482]: info: Upmpdcli Daemon Started Mar 27 10:28:59 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Mar 27 10:28:59 volumio44 wpa_supplicant[1188]: BSSID f8:b7:97:73:a3:23 ignore list count incremented to 3, ignoring for 60 seconds Mar 27 10:28:59 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-SSID-TEMP-DISABLED id=1 ssid="aterm-9f10fa-a" auth_failures=1 duration=10 reason=CONN_FAILED Mar 27 10:28:59 volumio44 volumio[482]: info: Received Get System Info Mar 27 10:28:59 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:28:59 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:28:59 volumio44 volumio[482]: info: Discovery: Getting this device information Mar 27 10:28:59 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:28:59 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:28:59 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:28:59 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:28:59 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:28:59 volumio44 volumio[482]: info: go-librespot daemon successfully initialized Mar 27 10:28:59 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Mar 27 10:28:59 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:59 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:28:59 volumio44 go-librespot[803]: go-librespot daemon starting... Mar 27 10:28:59 volumio44 go-librespot[804]: time="2026-03-27T10:28:59+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:28:59 volumio44 go-librespot[804]: time="2026-03-27T10:28:59+09:00" level=debug msg="app state loaded" Mar 27 10:28:59 volumio44 go-librespot[804]: time="2026-03-27T10:28:59+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:28:59 volumio44 go-librespot[804]: time="2026-03-27T10:28:59+09: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 27 10:28:59 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:28:59 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:00 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:29:00.209+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:29:02 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:02 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:03 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Mar 27 10:29:03 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:03 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:03 volumio44 go-librespot[812]: go-librespot daemon starting... Mar 27 10:29:03 volumio44 go-librespot[813]: time="2026-03-27T10:29:03+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:03 volumio44 go-librespot[813]: time="2026-03-27T10:29:03+09:00" level=debug msg="app state loaded" Mar 27 10:29:03 volumio44 go-librespot[813]: time="2026-03-27T10:29:03+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:03 volumio44 go-librespot[813]: time="2026-03-27T10:29:03+09: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 27 10:29:03 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:03 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:05 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:05 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:06 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Mar 27 10:29:06 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:06 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:06 volumio44 go-librespot[821]: go-librespot daemon starting... Mar 27 10:29:06 volumio44 go-librespot[822]: time="2026-03-27T10:29:06+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:06 volumio44 go-librespot[822]: time="2026-03-27T10:29:06+09:00" level=debug msg="app state loaded" Mar 27 10:29:06 volumio44 go-librespot[822]: time="2026-03-27T10:29:06+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:06 volumio44 go-librespot[822]: time="2026-03-27T10:29:06+09: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 27 10:29:06 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:06 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:06 volumio44 volumio[482]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.103&uuid=18ae9c01c43fcbb40f6c34bbe9080c24" http://updates.volumio.org/downloader-v1/track-device Mar 27 10:29:06 volumio44 volumio[482]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 27 10:29:06 volumio44 volumio[482]: Dload Upload Total Spent Left Speed Mar 27 10:29:06 volumio44 volumio[482]: [132B blob data] Mar 27 10:29:06 volumio44 volumio[482]: retrying in 5 seconds, trial 0 Mar 27 10:29:06 volumio44 volumio[482]: info: Volumio Calling Home Mar 27 10:29:08 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:08 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:09 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Mar 27 10:29:09 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:09 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:09 volumio44 go-librespot[847]: go-librespot daemon starting... Mar 27 10:29:09 volumio44 go-librespot[848]: time="2026-03-27T10:29:09+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:09 volumio44 go-librespot[848]: time="2026-03-27T10:29:09+09:00" level=debug msg="app state loaded" Mar 27 10:29:09 volumio44 go-librespot[848]: time="2026-03-27T10:29:09+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:09 volumio44 go-librespot[848]: time="2026-03-27T10:29:09+09: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 27 10:29:09 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:09 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:11 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:11 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:12 volumio44 volumio[482]: info: Received Get System Info Mar 27 10:29:12 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:29:12 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:29:12 volumio44 volumio[482]: info: Discovery: Getting this device information Mar 27 10:29:12 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:29:12 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:29:12 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:29:12 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:29:12 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:29:12 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Mar 27 10:29:12 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:12 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:12 volumio44 go-librespot[857]: go-librespot daemon starting... Mar 27 10:29:12 volumio44 go-librespot[858]: time="2026-03-27T10:29:12+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:12 volumio44 go-librespot[858]: time="2026-03-27T10:29:12+09:00" level=debug msg="app state loaded" Mar 27 10:29:12 volumio44 go-librespot[858]: time="2026-03-27T10:29:12+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:12 volumio44 go-librespot[858]: time="2026-03-27T10:29:12+09: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 27 10:29:12 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:12 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:13 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:29:13.280+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:29:14 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:14 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:16 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Mar 27 10:29:16 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:16 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:16 volumio44 go-librespot[866]: go-librespot daemon starting... Mar 27 10:29:16 volumio44 go-librespot[867]: time="2026-03-27T10:29:16+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:16 volumio44 go-librespot[867]: time="2026-03-27T10:29:16+09:00" level=debug msg="app state loaded" Mar 27 10:29:16 volumio44 go-librespot[867]: time="2026-03-27T10:29:16+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:16 volumio44 go-librespot[867]: time="2026-03-27T10:29:16+09: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 27 10:29:16 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:16 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:16 volumio44 volumio[482]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.103&uuid=18ae9c01c43fcbb40f6c34bbe9080c24" http://updates.volumio.org/downloader-v1/track-device Mar 27 10:29:16 volumio44 volumio[482]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 27 10:29:16 volumio44 volumio[482]: Dload Upload Total Spent Left Speed Mar 27 10:29:16 volumio44 volumio[482]: [132B blob data] Mar 27 10:29:16 volumio44 volumio[482]: retrying in 5 seconds, trial 1 Mar 27 10:29:16 volumio44 volumio[482]: info: Volumio Calling Home Mar 27 10:29:17 volumio44 volumio[482]: error: MyVolumio Plugin failed to start in a timely fashion Mar 27 10:29:17 volumio44 volumio[482]: [Metrics] CommandRouter: 29s 882.00ms Mar 27 10:29:17 volumio44 volumio[482]: info: CoreCommandRouter::volumiosetStartupVolume Mar 27 10:29:17 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 27 10:29:17 volumio44 volumio[482]: info: VolumeController:: Setting startup Volume 90 Mar 27 10:29:17 volumio44 volumio[482]: info: VolumeController::SetAlsaVolume90 Mar 27 10:29:17 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:29:17 volumio44 volumio[482]: info: CoreCommandRouter::Close All Modals sent Mar 27 10:29:17 volumio44 volumio[482]: info: CoreCommandRouter::Close All Modals sent Mar 27 10:29:17 volumio44 volumio[482]: info: CoreStateMachine::pushState Mar 27 10:29:17 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:29:17 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 10:29:17 volumio44 volumio[482]: info: CoreCommandRouter::volumioPushState Mar 27 10:29:17 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:17 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:18 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Mar 27 10:29:18 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Mar 27 10:29:18 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Mar 27 10:29:19 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Mar 27 10:29:19 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:19 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:19 volumio44 go-librespot[897]: go-librespot daemon starting... Mar 27 10:29:19 volumio44 go-librespot[898]: time="2026-03-27T10:29:19+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:19 volumio44 go-librespot[898]: time="2026-03-27T10:29:19+09:00" level=debug msg="app state loaded" Mar 27 10:29:19 volumio44 go-librespot[898]: time="2026-03-27T10:29:19+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:19 volumio44 go-librespot[898]: time="2026-03-27T10:29:19+09: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 27 10:29:19 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:19 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:19 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-SSID-REENABLED id=1 ssid="aterm-9f10fa-a" Mar 27 10:29:19 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-SSID-REENABLED id=2 ssid="aterm-9f10fa-g" Mar 27 10:29:19 volumio44 wpa_supplicant[1188]: wlan0: Trying to associate with f8:b7:97:73:a3:22 (SSID='aterm-9f10fa-g' freq=2462 MHz) Mar 27 10:29:19 volumio44 wpa_supplicant[1188]: wlan0: Associated with f8:b7:97:73:a3:22 Mar 27 10:29:19 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Mar 27 10:29:19 volumio44 wpa_supplicant[1188]: wlan0: WPA: Key negotiation completed with f8:b7:97:73:a3:22 [PTK=CCMP GTK=CCMP] Mar 27 10:29:19 volumio44 wpa_supplicant[1188]: wlan0: CTRL-EVENT-CONNECTED - Connection to f8:b7:97:73:a3:22 completed [id=2 id_str=] Mar 27 10:29:19 volumio44 dhcpcd[748]: wlan0: carrier acquired Mar 27 10:29:19 volumio44 dhcpcd[748]: wlan0: IAID 9e:5d:cc:dd Mar 27 10:29:20 volumio44 volumio[482]: info: Received Get System Info Mar 27 10:29:20 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:29:20 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:29:20 volumio44 volumio[482]: info: Discovery: Getting this device information Mar 27 10:29:20 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:29:20 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:29:20 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:29:20 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:29:20 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:29:20 volumio44 dhcpcd[748]: wlan0: soliciting an IPv6 router Mar 27 10:29:20 volumio44 dhcpcd[748]: wlan0: rebinding lease of 192.168.10.101 Mar 27 10:29:20 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:20 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:20 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:29:20.959+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:29:22 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Mar 27 10:29:22 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:22 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:22 volumio44 go-librespot[909]: go-librespot daemon starting... Mar 27 10:29:22 volumio44 go-librespot[910]: time="2026-03-27T10:29:22+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:22 volumio44 go-librespot[910]: time="2026-03-27T10:29:22+09:00" level=debug msg="app state loaded" Mar 27 10:29:22 volumio44 go-librespot[910]: time="2026-03-27T10:29:22+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:22 volumio44 go-librespot[910]: time="2026-03-27T10:29:22+09: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 27 10:29:22 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:22 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:23 volumio44 dhcpcd[748]: wlan0: probing address 192.168.10.101/24 Mar 27 10:29:23 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:23 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:24 volumio44 volumio[482]: info: BOOT COMPLETED Mar 27 10:29:25 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Mar 27 10:29:25 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:25 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:25 volumio44 go-librespot[918]: go-librespot daemon starting... Mar 27 10:29:25 volumio44 go-librespot[919]: time="2026-03-27T10:29:25+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:25 volumio44 go-librespot[919]: time="2026-03-27T10:29:25+09:00" level=debug msg="app state loaded" Mar 27 10:29:25 volumio44 go-librespot[919]: time="2026-03-27T10:29:25+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:25 volumio44 go-librespot[919]: time="2026-03-27T10:29:25+09: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 27 10:29:25 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:25 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:26 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 10:29:26 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 27 10:29:26 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 27 10:29:26 volumio44 volumio[482]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.103&uuid=18ae9c01c43fcbb40f6c34bbe9080c24" http://updates.volumio.org/downloader-v1/track-device Mar 27 10:29:26 volumio44 volumio[482]: % Total % Received % Xferd Average Speed Time Time Time Current Mar 27 10:29:26 volumio44 volumio[482]: Dload Upload Total Spent Left Speed Mar 27 10:29:26 volumio44 volumio[482]: [132B blob data] Mar 27 10:29:26 volumio44 volumio[482]: retrying in 5 seconds, trial 2 Mar 27 10:29:26 volumio44 volumio[482]: info: Volumio Calling Home Mar 27 10:29:26 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:26 volumio44 volumio[482]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:27 volumio44 dhcpcd[748]: wlan0: leased 192.168.10.101 for 86400 seconds Mar 27 10:29:27 volumio44 avahi-daemon[1350]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.10.101. Mar 27 10:29:27 volumio44 avahi-daemon[1350]: New relevant interface wlan0.IPv4 for mDNS. Mar 27 10:29:27 volumio44 avahi-daemon[1350]: Registering new address record for 192.168.10.101 on wlan0.IPv4. Mar 27 10:29:27 volumio44 dhcpcd[748]: wlan0: adding route to 192.168.10.0/24 Mar 27 10:29:27 volumio44 dhcpcd[748]: wlan0: adding default route via 192.168.10.1 Mar 27 10:29:27 volumio44 systemd[1]: Stopped target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 27 10:29:27 volumio44 systemd[1]: Stopping ip-changed@wlan0.target - IP Address changed on wlan0... Mar 27 10:29:27 volumio44 systemd[1]: welcome.service: Deactivated successfully. Mar 27 10:29:27 volumio44 systemd[1]: Stopped welcome.service - Show a welcome message on console. Mar 27 10:29:27 volumio44 systemd[1]: Stopping welcome.service - Show a welcome message on console... Mar 27 10:29:27 volumio44 systemd[1]: Starting welcome.service - Show a welcome message on console... Mar 27 10:29:27 volumio44 welcome[949]: Resolved ip:[1] 192.168.10.101 Mar 27 10:29:27 volumio44 systemd[1]: Finished welcome.service - Show a welcome message on console. Mar 27 10:29:27 volumio44 systemd[1]: Reached target ip-changed@wlan0.target - IP Address changed on wlan0. Mar 27 10:29:28 volumio44 volumio[482]: info: Received Get System Info Mar 27 10:29:28 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 27 10:29:28 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 27 10:29:28 volumio44 volumio[482]: info: Discovery: Getting this device information Mar 27 10:29:28 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:29:28 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:29:28 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 27 10:29:28 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 27 10:29:28 volumio44 volumio[482]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 27 10:29:28 volumio44 volumio[482]: info: Volumio Network Manager: Network status updated: 2 Mar 27 10:29:28 volumio44 volumio5-onboarding[1811]: time=2026-03-27T10:29:28.946+09:00 level=INFO msg="service successfully established" component=discovery/localnet Mar 27 10:29:29 volumio44 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Mar 27 10:29:29 volumio44 systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:29 volumio44 systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Mar 27 10:29:29 volumio44 go-librespot[981]: go-librespot daemon starting... Mar 27 10:29:29 volumio44 go-librespot[982]: time="2026-03-27T10:29:29+09:00" level=info msg="running go-librespot 0.7.1" Mar 27 10:29:29 volumio44 go-librespot[982]: time="2026-03-27T10:29:29+09:00" level=debug msg="app state loaded" Mar 27 10:29:29 volumio44 go-librespot[982]: time="2026-03-27T10:29:29+09:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 27 10:29:29 volumio44 ntpd[1048]: IO: Listen normally on 5 wlan0 192.168.10.101:123 Mar 27 10:29:29 volumio44 ntpd[1048]: IO: new interface(s) found: waking up resolver Mar 27 10:29:29 volumio44 volumio[482]: info: Initializing connection to go-librespot Websocket Mar 27 10:29:51 volumio44 volumio[482]: info: Discovery: this is already registered, d53f94ae-f88e-489a-b898-760151f1ab34 Mar 27 10:29:51 volumio44 volumio[482]: info: Discovery: Found device Volumio44 Mar 27 10:29:51 volumio44 volumio[482]: info: CoreCommandRouter::volumioGetState Mar 27 10:29:51 volumio44 volumio[482]: info: CorePlayQueue::getTrack 0 Mar 27 10:29:51 volumio44 go-librespot[982]: time="2026-03-27T10:29:51+09:00" level=debug msg="new websocket client" Mar 27 10:29:51 volumio44 volumio[482]: info: Connection to go-librespot Websocket established Mar 27 10:29:52 volumio44 go-librespot[982]: time="2026-03-27T10:29:52+09: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 27 10:29:52 volumio44 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 27 10:29:52 volumio44 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 27 10:29:52 volumio44 volumio[482]: info: Connection to go-librespot Websocket closed Mar 27 10:29:54 volumio44 volumio[482]: info: Getting Spotify volume Mar 27 10:29:54 volumio44 volumio[482]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 10:29:54 volumio44 volumio[482]: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 27 10:29:54 volumio44 volumio[482]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Mar 27 10:29:54 volumio44 volumio[482]: errno: -111, Mar 27 10:29:54 volumio44 volumio[482]: code: 'ECONNREFUSED', Mar 27 10:29:54 volumio44 volumio[482]: syscall: 'connect', Mar 27 10:29:54 volumio44 volumio[482]: address: '127.0.0.1', Mar 27 10:29:54 volumio44 volumio[482]: port: 9879, Mar 27 10:29:54 volumio44 volumio[482]: response: undefined Mar 27 10:29:54 volumio44 volumio[482]: } Mar 27 10:29:54 volumio44 volumio[482]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 10:29:54 volumio44 sudo[1035]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-27 10:28' Mar 27 10:29:54 volumio44 sudo[1035]: 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="dc61260dec5515dafd2b634881860b4c46c919ff" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026" VOLUMIO_VERSION="4.103" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"