Dec 11 05:11:00 volumio upmpdcli[1391]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Timeout Dec 11 05:11:00 volumio upmpdcli[1391]: :2:../src/mpdcli.cxx:396::MPDCli::updStatus: connection failed Dec 11 05:11:00 volumio upmpdcli[1391]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 Dec 11 05:11:00 volumio volumio[21859]: info: go-librespot daemon successfully initialized Dec 11 05:11:01 volumio mpd[22025]: 2025-12-11T05:11:01 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 11 05:11:01 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 11 05:11:01 volumio sudo[21995]: pam_unix(sudo:session): session closed for user root Dec 11 05:11:01 volumio sudo[21985]: pam_unix(sudo:session): session closed for user root Dec 11 05:11:01 volumio volumio[21859]: info: Completed starting Core Plugins Dec 11 05:11:01 volumio volumio[21859]: info: ------------------------------------------- Dec 11 05:11:01 volumio volumio[21859]: info: ----- MyVolumio plugins startup ---- Dec 11 05:11:01 volumio volumio[21859]: info: ------------------------------------------- Dec 11 05:11:01 volumio volumio[21859]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 11 05:11:01 volumio volumio[21859]: error: MPD error: The expression evaluated to a falsy value: Dec 11 05:11:01 volumio volumio[21859]: assert.ok(self.idling) Dec 11 05:11:01 volumio volumio[21859]: error: The expression evaluated to a falsy value: Dec 11 05:11:01 volumio volumio[21859]: assert.ok(self.idling) Dec 11 05:11:01 volumio volumio[21859]: info: MPD running with PID22025 Dec 11 05:11:01 volumio volumio[21859]: ,establishing connection Dec 11 05:11:01 volumio volumio[21859]: error: updateQueue error: null Dec 11 05:11:01 volumio volumio[21859]: error: updateQueue error: null Dec 11 05:11:02 volumio upmpdcli[1391]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started Dec 11 05:11:03 volumio volumio[21859]: info: Initializing connection to go-librespot Websocket Dec 11 05:11:04 volumio sudo[22131]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 11 05:11:04 volumio sudo[22131]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 11 05:11:04 volumio sudo[22133]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 11 05:11:04 volumio sudo[22133]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 11 05:11:04 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 11 05:11:04 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 11 05:11:04 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 11 05:11:04 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 11 05:11:04 volumio sudo[22133]: pam_unix(sudo:session): session closed for user root Dec 11 05:11:04 volumio sudo[22131]: pam_unix(sudo:session): session closed for user root Dec 11 05:11:04 volumio mpd_monitor.sh[22136]: MPD Monitor Service: Starting MPD Monitor Service Dec 11 05:11:04 volumio volumio[21859]: info: Successfully started MPD Monitor Dec 11 05:11:04 volumio volumio[21859]: info: Successfully started MPD Monitor Dec 11 05:11:06 volumio volumio[21859]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 11 05:11:06 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:06 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:09 volumio go-librespot[22077]: time="2025-12-11T05:11:09-05: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" Dec 11 05:11:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 11 05:11:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 11 05:11:11 volumio kernel: hwmon hwmon1: Voltage normalised Dec 11 05:11:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 11 05:11:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 11 05:11:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 11 05:11:12 volumio go-librespot[22155]: go-librespot daemon starting... Dec 11 05:11:12 volumio go-librespot[22156]: time="2025-12-11T05:11:12-05:00" level=info msg="running go-librespot 0.4.0" Dec 11 05:11:12 volumio go-librespot[22156]: time="2025-12-11T05:11:12-05:00" level=debug msg="app state loaded" Dec 11 05:11:12 volumio go-librespot[22156]: time="2025-12-11T05:11:12-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 11 05:11:14 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 11 05:11:16 volumio volumio[21859]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.073&uuid=c24d66a30dea23391915b074d4b54fde" http://updates.volumio.org/downloader-v1/track-device Dec 11 05:11:16 volumio volumio[21859]: % Total % Received % Xferd Average Speed Time Time Time Current Dec 11 05:11:16 volumio volumio[21859]: Dload Upload Total Spent Left Speed Dec 11 05:11:16 volumio volumio[21859]: [1001B blob data] Dec 11 05:11:16 volumio volumio[21859]: retrying in 5 seconds, trial 0 Dec 11 05:11:16 volumio volumio[21859]: info: Volumio Calling Home Dec 11 05:11:16 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:16 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:16 volumio volumio[21859]: info: Listing playlists Dec 11 05:11:16 volumio volumio[21859]: info: Listing playlists Dec 11 05:11:18 volumio volumio[21859]: info: Discovery: adding 8db2539d-a5e0-4269-ad1e-3740b4b0fc62 Dec 11 05:11:18 volumio volumio[21859]: info: Discovery: Found device Volumio Dec 11 05:11:18 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:18 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:18 volumio volumio[21859]: info: Discovery: this is already registered, 8db2539d-a5e0-4269-ad1e-3740b4b0fc62 Dec 11 05:11:18 volumio volumio[21859]: info: Discovery: Found device Volumio Dec 11 05:11:18 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:18 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:18 volumio volumio[21859]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 11 05:11:21 volumio volumio[21859]: error: MyVolumio Plugin failed to start in a timely fashion Dec 11 05:11:21 volumio volumio[21859]: [Metrics] CommandRouter: 39s 237.83ms Dec 11 05:11:21 volumio volumio[21859]: info: CoreCommandRouter::volumiosetStartupVolume Dec 11 05:11:21 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 11 05:11:21 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 11 05:11:21 volumio volumio[21859]: info: CoreCommandRouter::Close All Modals sent Dec 11 05:11:21 volumio volumio[21859]: info: CoreCommandRouter::Close All Modals sent Dec 11 05:11:22 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 11 05:11:22 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 11 05:11:22 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 11 05:11:24 volumio go-librespot[22156]: time="2025-12-11T05:11:24-05: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" Dec 11 05:11:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 11 05:11:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 11 05:11:25 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Dec 11 05:11:25 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 11 05:11:25 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 11 05:11:25 volumio volumio[21859]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 11 05:11:26 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:26 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 11 05:11:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 11 05:11:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 11 05:11:28 volumio go-librespot[22221]: go-librespot daemon starting... Dec 11 05:11:28 volumio go-librespot[22222]: time="2025-12-11T05:11:28-05:00" level=info msg="running go-librespot 0.4.0" Dec 11 05:11:28 volumio go-librespot[22222]: time="2025-12-11T05:11:28-05:00" level=debug msg="app state loaded" Dec 11 05:11:28 volumio go-librespot[22222]: time="2025-12-11T05:11:28-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 11 05:11:28 volumio volumio[21859]: info: BOOT COMPLETED Dec 11 05:11:36 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:36 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:36 volumio volumio[21859]: info: Listing playlists Dec 11 05:11:37 volumio volumio[21859]: info: Listing playlists Dec 11 05:11:37 volumio volumio[21859]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo ENOTFOUND oauth-performer.prod.vlmapi.io Dec 11 05:11:38 volumio volumio[21859]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.073&uuid=c24d66a30dea23391915b074d4b54fde" http://updates.volumio.org/downloader-v1/track-device Dec 11 05:11:38 volumio volumio[21859]: % Total % Received % Xferd Average Speed Time Time Time Current Dec 11 05:11:38 volumio volumio[21859]: Dload Upload Total Spent Left Speed Dec 11 05:11:38 volumio volumio[21859]: [1001B blob data] Dec 11 05:11:38 volumio volumio[21859]: retrying in 5 seconds, trial 1 Dec 11 05:11:38 volumio volumio[21859]: info: Volumio Calling Home Dec 11 05:11:46 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:46 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:48 volumio go-librespot[22222]: time="2025-12-11T05:11:48-05: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" Dec 11 05:11:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 11 05:11:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 11 05:11:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 11 05:11:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 11 05:11:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 11 05:11:51 volumio go-librespot[22263]: go-librespot daemon starting... Dec 11 05:11:51 volumio go-librespot[22264]: time="2025-12-11T05:11:51-05:00" level=info msg="running go-librespot 0.4.0" Dec 11 05:11:51 volumio go-librespot[22264]: time="2025-12-11T05:11:51-05:00" level=debug msg="app state loaded" Dec 11 05:11:51 volumio go-librespot[22264]: time="2025-12-11T05:11:51-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 11 05:11:55 volumio go-librespot[22264]: time="2025-12-11T05:11:55-05:00" level=debug msg="new websocket client" Dec 11 05:11:55 volumio volumio[21859]: info: Connection to go-librespot Websocket established Dec 11 05:11:55 volumio volumio[21859]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 11 05:11:57 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:11:57 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:11:57 volumio volumio[21859]: info: Listing playlists Dec 11 05:11:57 volumio volumio[21859]: info: Listing playlists Dec 11 05:11:58 volumio volumio[21859]: info: Getting Spotify volume Dec 11 05:12:06 volumio volumio[21859]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.073&uuid=c24d66a30dea23391915b074d4b54fde" http://updates.volumio.org/downloader-v1/track-device Dec 11 05:12:06 volumio volumio[21859]: % Total % Received % Xferd Average Speed Time Time Time Current Dec 11 05:12:06 volumio volumio[21859]: Dload Upload Total Spent Left Speed Dec 11 05:12:06 volumio volumio[21859]: [1.5K blob data] Dec 11 05:12:06 volumio volumio[21859]: retrying in 5 seconds, trial 2 Dec 11 05:12:06 volumio volumio[21859]: info: Volumio Calling Home Dec 11 05:12:06 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:12:06 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:12:09 volumio volumio[21859]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 11 05:12:09 volumio volumio[21859]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Dec 11 05:12:09 volumio volumio[21859]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Dec 11 05:12:09 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:12:09 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:12:09 volumio volumio[21859]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 11 05:12:09 volumio volumio[21859]: SPOTIFY: SPOTIFY VOLUME undefined Dec 11 05:12:09 volumio volumio[21859]: SPOTIFY: VOLUMIO VOLUME 86 Dec 11 05:12:09 volumio volumio[21859]: info: Aligning Spotify Volume to Volumio Volume Dec 11 05:12:09 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:12:09 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:12:09 volumio volumio[21859]: info: Setting Spotify Volume from Volumio: 86 Dec 11 05:12:09 volumio volumio[21859]: info: CoreCommandRouter::volumioGetState Dec 11 05:12:09 volumio volumio[21859]: info: CorePlayQueue::getTrack 0 Dec 11 05:12:11 volumio volumio[21859]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Dec 11 05:12:11 volumio volumio[21859]: info: Sending Spotify command with payload to local API: /player/volume Dec 11 05:12:14 volumio go-librespot[22264]: time="2025-12-11T05:12:14-05: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" Dec 11 05:12:14 volumio volumio[21859]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Dec 11 05:12:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 11 05:12:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 11 05:12:14 volumio volumio[21859]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 11 05:12:14 volumio volumio[21859]: Error: socket hang up Dec 11 05:12:14 volumio volumio[21859]: at connResetException (node:internal/errors:720:14) Dec 11 05:12:14 volumio volumio[21859]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 11 05:12:14 volumio volumio[21859]: at Socket.emit (node:events:526:35) Dec 11 05:12:14 volumio volumio[21859]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 11 05:12:14 volumio volumio[21859]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 11 05:12:14 volumio volumio[21859]: code: 'ECONNRESET', Dec 11 05:12:14 volumio volumio[21859]: response: undefined Dec 11 05:12:14 volumio volumio[21859]: } Dec 11 05:12:14 volumio volumio[21859]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 11 05:12:16 volumio sudo[22320]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-11 05:11' Dec 11 05:12:16 volumio sudo[22320]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"