Jan 11 16:13:00 volumio go-librespot[4693]: time="2026-01-11T16:13:00+01: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" Jan 11 16:13:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:13:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:13:01 volumio volumio[4350]: info: AutoStart - Check #4/60 - VOLUMIO_SYSTEM_STATUS = starting Jan 11 16:13:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Jan 11 16:13:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:03 volumio go-librespot[4793]: go-librespot daemon starting... Jan 11 16:13:03 volumio go-librespot[4794]: time="2026-01-11T16:13:03+01:00" level=info msg="running go-librespot 0.6.2" Jan 11 16:13:03 volumio go-librespot[4794]: time="2026-01-11T16:13:03+01:00" level=debug msg="app state loaded" Jan 11 16:13:03 volumio go-librespot[4794]: time="2026-01-11T16:13:03+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:13:05 volumio volumio[4350]: info: Discovery: adding 8400c09d-53a3-4e9d-b9dc-1fdea9855bf6 Jan 11 16:13:05 volumio volumio[4350]: info: Discovery: Found device Volumio Jan 11 16:13:05 volumio volumio[4350]: info: CoreCommandRouter::volumioGetState Jan 11 16:13:05 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:05 volumio volumio[4350]: info: Discovery: this is already registered, 8400c09d-53a3-4e9d-b9dc-1fdea9855bf6 Jan 11 16:13:05 volumio volumio[4350]: info: Discovery: Found device Volumio Jan 11 16:13:05 volumio volumio[4350]: info: CoreCommandRouter::volumioGetState Jan 11 16:13:05 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:05 volumio volumio[4350]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Jan 11 16:13:05 volumio volumio[4350]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.073&uuid=0f95083359b1853849a950760fdd2d4b" http://updates.volumio.org/downloader-v1/track-device Jan 11 16:13:05 volumio volumio[4350]: % Total % Received % Xferd Average Speed Time Time Time Current Jan 11 16:13:05 volumio volumio[4350]: Dload Upload Total Spent Left Speed Jan 11 16:13:05 volumio volumio[4350]: [843B blob data] Jan 11 16:13:05 volumio volumio[4350]: retrying in 5 seconds, trial 0 Jan 11 16:13:05 volumio volumio[4350]: info: Volumio Calling Home Jan 11 16:13:06 volumio volumio[4350]: info: AutoStart - Check #5/60 - VOLUMIO_SYSTEM_STATUS = starting Jan 11 16:13:09 volumio volumio[4350]: error: MyVolumio Plugin failed to start in a timely fashion Jan 11 16:13:09 volumio volumio[4350]: [Metrics] CommandRouter: 28s 537.01ms Jan 11 16:13:09 volumio volumio[4350]: info: CoreCommandRouter::volumiosetStartupVolume Jan 11 16:13:09 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 11 16:13:09 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:13:09 volumio volumio[4350]: info: CoreCommandRouter::Close All Modals sent Jan 11 16:13:09 volumio volumio[4350]: info: CoreCommandRouter::Close All Modals sent Jan 11 16:13:10 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jan 11 16:13:10 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 11 16:13:10 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jan 11 16:13:11 volumio volumio[4350]: info: AutoStart - Check #6/60 - VOLUMIO_SYSTEM_STATUS = starting Jan 11 16:13:14 volumio kernel: xhci_hcd 0000:01:00.0: ERROR Transfer event for disabled endpoint slot 2 ep 1 Jan 11 16:13:14 volumio kernel: xhci_hcd 0000:01:00.0: @0000000428d20160 00000000 00000000 0e000000 02028001 Jan 11 16:13:16 volumio go-librespot[4794]: time="2026-01-11T16:13:16+01: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" Jan 11 16:13:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:13:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:13:16 volumio volumio[4350]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo ENOTFOUND oauth-performer.prod.vlmapi.io Jan 11 16:13:16 volumio volumio[4350]: info: AutoStart - Check #7/60 - VOLUMIO_SYSTEM_STATUS = starting Jan 11 16:13:16 volumio volumio[4350]: info: BOOT COMPLETED Jan 11 16:13:16 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 11 16:13:16 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 11 16:13:16 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 11 16:13:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Jan 11 16:13:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:19 volumio go-librespot[4832]: go-librespot daemon starting... Jan 11 16:13:19 volumio go-librespot[4833]: time="2026-01-11T16:13:19+01:00" level=info msg="running go-librespot 0.6.2" Jan 11 16:13:19 volumio go-librespot[4833]: time="2026-01-11T16:13:19+01:00" level=debug msg="app state loaded" Jan 11 16:13:19 volumio go-librespot[4833]: time="2026-01-11T16:13:19+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:13:21 volumio volumio[4350]: info: AutoStart - Check #8/60 - VOLUMIO_SYSTEM_STATUS = ready Jan 11 16:13:21 volumio volumio[4350]: info: AutoStart - System ready state CONFIRMED after 8 checks Jan 11 16:13:21 volumio volumio[4350]: info: AutoStart - Applying additional delay of 5000ms before playback Jan 11 16:13:26 volumio volumio[4350]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.073&uuid=0f95083359b1853849a950760fdd2d4b" http://updates.volumio.org/downloader-v1/track-device Jan 11 16:13:26 volumio volumio[4350]: % Total % Received % Xferd Average Speed Time Time Time Current Jan 11 16:13:26 volumio volumio[4350]: Dload Upload Total Spent Left Speed Jan 11 16:13:26 volumio volumio[4350]: [1001B blob data] Jan 11 16:13:26 volumio volumio[4350]: retrying in 5 seconds, trial 1 Jan 11 16:13:26 volumio volumio[4350]: info: Volumio Calling Home Jan 11 16:13:26 volumio volumio[4350]: info: AutoStart - startPlayback called Jan 11 16:13:26 volumio volumio[4350]: info: CoreCommandRouter::volumioGetQueue Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::getQueue Jan 11 16:13:26 volumio volumio[4350]: info: CorePlayQueue::getQueue Jan 11 16:13:26 volumio volumio[4350]: info: AutoStart - Queue has 1 items Jan 11 16:13:26 volumio volumio[4350]: info: AutoStart - Playing from position 0 Jan 11 16:13:26 volumio volumio[4350]: info: CoreCommandRouter::volumioPlay Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::play index 0 Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::stop Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::play index undefined Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 16:13:26 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::startPlaybackTimer Jan 11 16:13:26 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand stop Jan 11 16:13:26 volumio volumio[4350]: info: sendMpdCommand stop took 1 milliseconds Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand clear Jan 11 16:13:26 volumio volumio[4350]: info: Jan 11 16:13:26 volumio volumio[4350]: ---------------------------- MPD announces system playlist update Jan 11 16:13:26 volumio volumio[4350]: info: Ignoring MPD Status Update Jan 11 16:13:26 volumio volumio[4350]: info: sendMpdCommand clear took 2 milliseconds Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand consume 1 Jan 11 16:13:26 volumio volumio[4350]: info: Jan 11 16:13:26 volumio volumio[4350]: ---------------------------- MPD announces system playlist update Jan 11 16:13:26 volumio volumio[4350]: info: Ignoring MPD Status Update Jan 11 16:13:26 volumio volumio[4350]: error: updateQueue error: null Jan 11 16:13:26 volumio volumio[4350]: info: Jan 11 16:13:26 volumio volumio[4350]: ---------------------------- MPD announces state update: options Jan 11 16:13:26 volumio volumio[4350]: error: updateQueue error: null Jan 11 16:13:26 volumio volumio[4350]: info: ------------------------------ 5ms Jan 11 16:13:26 volumio volumio[4350]: info: sendMpdCommand consume 1 took 3 milliseconds Jan 11 16:13:26 volumio volumio[4350]: info: ControllerMpd::getState Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand status Jan 11 16:13:26 volumio volumio[4350]: info: ------------------------------ 4ms Jan 11 16:13:26 volumio volumio[4350]: info: [1768144406422] [MotherEarth] set to consume mode, adding url: https://motherearth.streamserver24.com/listen/motherearth_jazz/motherearth.jazz Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand add "https://motherearth.streamserver24.com/listen/motherearth_jazz/motherearth.jazz" Jan 11 16:13:26 volumio volumio[4350]: info: Jan 11 16:13:26 volumio volumio[4350]: ---------------------------- MPD announces state update: options Jan 11 16:13:26 volumio volumio[4350]: info: ControllerMpd::getState Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand status Jan 11 16:13:26 volumio volumio[4350]: info: Jan 11 16:13:26 volumio volumio[4350]: ---------------------------- MPD announces system playlist update Jan 11 16:13:26 volumio volumio[4350]: info: Ignoring MPD Status Update Jan 11 16:13:26 volumio volumio[4350]: info: sendMpdCommand status took 4 milliseconds Jan 11 16:13:26 volumio volumio[4350]: info: sendMpdCommand add "https://motherearth.streamserver24.com/listen/motherearth_jazz/motherearth.jazz" took 3 milliseconds Jan 11 16:13:26 volumio volumio[4350]: info: sendMpdCommand status took 3 milliseconds Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::parseState Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand play Jan 11 16:13:26 volumio volumio[4350]: verbose: ControllerMpd::parseState Jan 11 16:13:26 volumio volumio[4350]: info: ControllerMpd::pushState Jan 11 16:13:26 volumio volumio[4350]: info: CoreCommandRouter::servicePushState Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::pushState Jan 11 16:13:26 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:26 volumio volumio[4350]: info: CoreCommandRouter::volumioPushState Jan 11 16:13:26 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:26 volumio volumio[4350]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current motherearthradio Received mpd Jan 11 16:13:26 volumio volumio[4350]: info: ControllerMpd::pushState Jan 11 16:13:26 volumio volumio[4350]: info: CoreCommandRouter::servicePushState Jan 11 16:13:26 volumio volumio[4350]: info: CoreStateMachine::pushState Jan 11 16:13:26 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:26 volumio volumio[4350]: info: CoreCommandRouter::volumioPushState Jan 11 16:13:26 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:26 volumio volumio[4350]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current motherearthradio Received mpd Jan 11 16:13:26 volumio volumio[4350]: info: ------------------------------ 29ms Jan 11 16:13:26 volumio volumio[4350]: info: ------------------------------ 28ms Jan 11 16:13:26 volumio volumio[4350]: info: Jan 11 16:13:26 volumio volumio[4350]: ---------------------------- MPD announces system playlist update Jan 11 16:13:26 volumio volumio[4350]: info: Ignoring MPD Status Update Jan 11 16:13:26 volumio volumio[4350]: info: ------------------------------ 31ms Jan 11 16:13:26 volumio volumio[4350]: info: sendMpdCommand play took 26 milliseconds Jan 11 16:13:26 volumio volumio[4350]: info: ------------------------------ 10ms Jan 11 16:13:28 volumio go-librespot[4833]: time="2026-01-11T16:13:28+01: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" Jan 11 16:13:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:13:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:13:28 volumio volumio[4350]: info: Error connecting to go-librespot Websocket: Error: read ECONNRESET Jan 11 16:13:28 volumio volumio[4350]: info: Error connecting to go-librespot Websocket: Error: read ECONNRESET Jan 11 16:13:31 volumio volumio[4350]: info: Initializing connection to go-librespot Websocket Jan 11 16:13:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Jan 11 16:13:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:31 volumio go-librespot[4862]: go-librespot daemon starting... Jan 11 16:13:31 volumio go-librespot[4863]: time="2026-01-11T16:13:31+01:00" level=info msg="running go-librespot 0.6.2" Jan 11 16:13:31 volumio go-librespot[4863]: time="2026-01-11T16:13:31+01:00" level=debug msg="app state loaded" Jan 11 16:13:31 volumio go-librespot[4863]: time="2026-01-11T16:13:31+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:13:34 volumio volumio[4350]: info: Jan 11 16:13:34 volumio volumio[4350]: ---------------------------- MPD announces state update: player Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::getState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand status Jan 11 16:13:34 volumio volumio[4350]: info: Jan 11 16:13:34 volumio volumio[4350]: ---------------------------- MPD announces state update: player Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::getState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand status Jan 11 16:13:34 volumio volumio[4350]: info: Jan 11 16:13:34 volumio volumio[4350]: ---------------------------- MPD announces state update: player Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::getState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand status Jan 11 16:13:34 volumio volumio[4350]: info: Jan 11 16:13:34 volumio volumio[4350]: ---------------------------- MPD announces state update: player Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand clearerror Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand status took 10 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::getState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand status Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand clearerror Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand status took 10 milliseconds Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand clearerror Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand status took 15 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand clearerror took 10 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand status took 10 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand clearerror took 9 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand playlistinfo took 6 milliseconds Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseState Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseTrackInfo Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseTrackInfo Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::servicePushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreStateMachine::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::volumioPushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current motherearthradio Received mpd Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::servicePushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreStateMachine::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::volumioPushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current motherearthradio Received mpd Jan 11 16:13:34 volumio volumio[4350]: info: ------------------------------ 46ms Jan 11 16:13:34 volumio volumio[4350]: info: ------------------------------ 43ms Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand clearerror took 25 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand playlistinfo took 22 milliseconds Jan 11 16:13:34 volumio volumio[4350]: info: sendMpdCommand playlistinfo took 22 milliseconds Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseTrackInfo Jan 11 16:13:34 volumio volumio[4350]: verbose: ControllerMpd::parseTrackInfo Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::servicePushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreStateMachine::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::volumioPushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current motherearthradio Received mpd Jan 11 16:13:34 volumio volumio[4350]: info: ControllerMpd::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::servicePushState Jan 11 16:13:34 volumio volumio[4350]: info: CoreStateMachine::pushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: CoreCommandRouter::volumioPushState Jan 11 16:13:34 volumio volumio[4350]: info: CorePlayQueue::getTrack 0 Jan 11 16:13:34 volumio volumio[4350]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current motherearthradio Received mpd Jan 11 16:13:34 volumio volumio[4350]: info: ------------------------------ 60ms Jan 11 16:13:34 volumio volumio[4350]: info: ------------------------------ 59ms Jan 11 16:13:44 volumio go-librespot[4863]: time="2026-01-11T16:13:44+01: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" Jan 11 16:13:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:13:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:13:44 volumio volumio[4350]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.073&uuid=0f95083359b1853849a950760fdd2d4b" http://updates.volumio.org/downloader-v1/track-device Jan 11 16:13:44 volumio volumio[4350]: % Total % Received % Xferd Average Speed Time Time Time Current Jan 11 16:13:44 volumio volumio[4350]: Dload Upload Total Spent Left Speed Jan 11 16:13:44 volumio volumio[4350]: [764B blob data] Jan 11 16:13:44 volumio volumio[4350]: retrying in 5 seconds, trial 2 Jan 11 16:13:44 volumio volumio[4350]: info: Volumio Calling Home Jan 11 16:13:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Jan 11 16:13:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:47 volumio go-librespot[4905]: go-librespot daemon starting... Jan 11 16:13:47 volumio go-librespot[4906]: time="2026-01-11T16:13:47+01:00" level=info msg="running go-librespot 0.6.2" Jan 11 16:13:47 volumio go-librespot[4906]: time="2026-01-11T16:13:47+01:00" level=debug msg="app state loaded" Jan 11 16:13:47 volumio go-librespot[4906]: time="2026-01-11T16:13:47+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:13:56 volumio go-librespot[4906]: time="2026-01-11T16:13:56+01: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" Jan 11 16:13:56 volumio volumio[4350]: info: [1768144436432] [MotherEarth] Error: getaddrinfo ENOTFOUND motherearth.streamserver24.com Jan 11 16:13:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:13:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:13:56 volumio volumio[4350]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 16:13:59 volumio volumio[4350]: info: Initializing connection to go-librespot Websocket Jan 11 16:13:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Jan 11 16:13:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:13:59 volumio go-librespot[4932]: go-librespot daemon starting... Jan 11 16:13:59 volumio go-librespot[4933]: time="2026-01-11T16:13:59+01:00" level=info msg="running go-librespot 0.6.2" Jan 11 16:13:59 volumio go-librespot[4933]: time="2026-01-11T16:13:59+01:00" level=debug msg="app state loaded" Jan 11 16:13:59 volumio go-librespot[4933]: time="2026-01-11T16:13:59+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:14:07 volumio go-librespot[4933]: time="2026-01-11T16:14:07+01: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" Jan 11 16:14:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:14:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:14:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Jan 11 16:14:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:14:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:14:10 volumio go-librespot[4956]: go-librespot daemon starting... Jan 11 16:14:10 volumio go-librespot[4957]: time="2026-01-11T16:14:10+01:00" level=info msg="running go-librespot 0.6.2" Jan 11 16:14:10 volumio go-librespot[4957]: time="2026-01-11T16:14:10+01:00" level=debug msg="app state loaded" Jan 11 16:14:10 volumio go-librespot[4957]: time="2026-01-11T16:14:10+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:14:19 volumio go-librespot[4957]: time="2026-01-11T16:14:19+01: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" Jan 11 16:14:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 11 16:14:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 11 16:14:19 volumio volumio[4350]: info: Connection to go-librespot Websocket established Jan 11 16:14:19 volumio volumio[4350]: info: Connection to go-librespot Websocket closed Jan 11 16:14:21 volumio dhcpcd[792]: eth0: offered 192.168.178.88 from 192.168.178.1 Jan 11 16:14:22 volumio dhcpcd[792]: eth0: probing address 192.168.178.88/24 Jan 11 16:14:22 volumio volumio[4350]: info: Getting Spotify volume Jan 11 16:14:22 volumio volumio[4350]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 16:14:22 volumio volumio[4350]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 11 16:14:22 volumio volumio[4350]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 11 16:14:22 volumio volumio[4350]: errno: -111, Jan 11 16:14:22 volumio volumio[4350]: code: 'ECONNREFUSED', Jan 11 16:14:22 volumio volumio[4350]: syscall: 'connect', Jan 11 16:14:22 volumio volumio[4350]: address: '127.0.0.1', Jan 11 16:14:22 volumio volumio[4350]: port: 9879, Jan 11 16:14:22 volumio volumio[4350]: response: undefined Jan 11 16:14:22 volumio volumio[4350]: } Jan 11 16:14:22 volumio volumio[4350]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 16:14:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Jan 11 16:14:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:14:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 11 16:14:22 volumio go-librespot[4997]: go-librespot daemon starting... Jan 11 16:14:22 volumio go-librespot[5009]: time="2026-01-11T16:14:22+01:00" level=info msg="running go-librespot 0.6.2" Jan 11 16:14:22 volumio go-librespot[5009]: time="2026-01-11T16:14:22+01:00" level=debug msg="app state loaded" Jan 11 16:14:22 volumio go-librespot[5009]: time="2026-01-11T16:14:22+01:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 11 16:14:22 volumio sudo[5019]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 16:13' Jan 11 16:14:22 volumio sudo[5019]: 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"