May 25 19:54:02 kjellerstue-volumio volumio[3768]: info: Cannot mount NAS hall at system boot, trial number 3 ,retrying in 5 seconds May 25 19:54:02 kjellerstue-volumio go-librespot[3823]: time="2026-05-25T19:54:02+02: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" May 25 19:54:02 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 25 19:54:02 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 25 19:54:05 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. May 25 19:54:05 kjellerstue-volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:05 kjellerstue-volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:05 kjellerstue-volumio go-librespot[3922]: go-librespot daemon starting... May 25 19:54:05 kjellerstue-volumio go-librespot[3923]: time="2026-05-25T19:54:05+02:00" level=info msg="running go-librespot 0.4.0" May 25 19:54:05 kjellerstue-volumio go-librespot[3923]: time="2026-05-25T19:54:05+02:00" level=debug msg="app state loaded" May 25 19:54:05 kjellerstue-volumio go-librespot[3923]: time="2026-05-25T19:54:05+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 25 19:54:07 kjellerstue-volumio volumio[3768]: info: Cannot mount NAS hall at system boot, trial number 4 ,retrying in 5 seconds May 25 19:54:10 kjellerstue-volumio key.dns_resolver[3883]: hall: No address associated with name May 25 19:54:12 kjellerstue-volumio volumio[3768]: info: Cannot mount NAS at system boot, trial number 4 ,stopping May 25 19:54:18 kjellerstue-volumio sudo[3797]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Discovery: adding 8df23f43-e8d9-42d2-93ea-7c6dc22ac547 May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Discovery: Found device kjellerstue (volumio) May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioGetState May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CorePlayQueue::getTrack 0 May 25 19:54:18 kjellerstue-volumio go-librespot[3923]: time="2026-05-25T19:54:18+02: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" May 25 19:54:18 kjellerstue-volumio sudo[3799]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:18 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Discovery: this is already registered, 8df23f43-e8d9-42d2-93ea-7c6dc22ac547 May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Discovery: Found device kjellerstue (volumio) May 25 19:54:18 kjellerstue-volumio sudo[3797]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 25 19:54:18 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioGetState May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CorePlayQueue::getTrack 0 May 25 19:54:18 kjellerstue-volumio sudo[3797]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:18 kjellerstue-volumio sudo[3799]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 25 19:54:18 kjellerstue-volumio sudo[3799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:18 kjellerstue-volumio sudo[3799]: pam_unix(sudo:session): session closed for user root May 25 19:54:18 kjellerstue-volumio sudo[3797]: pam_unix(sudo:session): session closed for user root May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Completed loading Core Plugins May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Preparing to generate the ALSA configuration file May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Asound.conf file unchanged, so no further update is needed May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Output device has changed, restarting MPD May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Output device has changed, restarting Shairport Sync May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: ___________ START PLUGINS ___________ May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: ControllerMpd::onStart: Initializing MPD May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Creating MPD Configuration file May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: [1779731658692] CoreMusicLibrary::Adding element Media Servers May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: UPNP Browser: Client initialized successfully May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: [1779731658743] CoreMusicLibrary::Adding element Last_100 May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: [1779731658745] CoreMusicLibrary::Adding element Webradio May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Initializing BBC Radios May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: [1779731658788] CoreMusicLibrary::Adding element Bandcamp Discover May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 19:54:18 kjellerstue-volumio volumio[3768]: Cannot find translation for source Bandcamp Discover May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: [1779731658794] CoreMusicLibrary::Adding element SoundCloud May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 25 19:54:18 kjellerstue-volumio volumio[3768]: Cannot find translation for source Bandcamp Discover May 25 19:54:18 kjellerstue-volumio volumio[3768]: Cannot find translation for source SoundCloud May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Creating Spotify config file May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:18 kjellerstue-volumio volumio[3768]: info: Volumio Calling Home May 25 19:54:19 kjellerstue-volumio volumio[3768]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: Spotify config file written May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: No need to fix Spotify hosts May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: Starting Shairport Sync May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: Starting Shairport Sync May 25 19:54:19 kjellerstue-volumio volumio[3768]: info: Starting Shairport Sync May 25 19:54:21 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. May 25 19:54:21 kjellerstue-volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:21 kjellerstue-volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:21 kjellerstue-volumio go-librespot[4003]: go-librespot daemon starting... May 25 19:54:21 kjellerstue-volumio go-librespot[4004]: time="2026-05-25T19:54:21+02:00" level=info msg="running go-librespot 0.4.0" May 25 19:54:21 kjellerstue-volumio go-librespot[4004]: time="2026-05-25T19:54:21+02:00" level=debug msg="app state loaded" May 25 19:54:21 kjellerstue-volumio go-librespot[4004]: time="2026-05-25T19:54:21+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 25 19:54:30 kjellerstue-volumio sudo[3919]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:30 kjellerstue-volumio key.dns_resolver[3944]: hall: No address associated with name May 25 19:54:30 kjellerstue-volumio sudo[3921]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:30 kjellerstue-volumio sudo[3919]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 25 19:54:30 kjellerstue-volumio sudo[3919]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:30 kjellerstue-volumio sudo[3917]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:30 kjellerstue-volumio sudo[3921]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 25 19:54:30 kjellerstue-volumio sudo[3921]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:30 kjellerstue-volumio sudo[3919]: pam_unix(sudo:session): session closed for user root May 25 19:54:30 kjellerstue-volumio sudo[3917]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 25 19:54:30 kjellerstue-volumio sudo[3917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:30 kjellerstue-volumio volumio[3768]: info: An error occurred while refreshing Spotify Token Error: getaddrinfo ENOTFOUND oauth-performer.prod.vlmapi.io May 25 19:54:30 kjellerstue-volumio sudo[3917]: pam_unix(sudo:session): session closed for user root May 25 19:54:30 kjellerstue-volumio sudo[3921]: pam_unix(sudo:session): session closed for user root May 25 19:54:30 kjellerstue-volumio volumio[3768]: info: Upmpdcli Daemon Started May 25 19:54:38 kjellerstue-volumio go-librespot[4004]: time="2026-05-25T19:54:38+02: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" May 25 19:54:38 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 25 19:54:38 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 25 19:54:40 kjellerstue-volumio volumio[3768]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=4.119&uuid=74708406243dd75fa23f40ab88d0f986" http://updates.volumio.org/downloader-v1/track-device May 25 19:54:40 kjellerstue-volumio volumio[3768]: % Total % Received % Xferd Average Speed Time Time Time Current May 25 19:54:40 kjellerstue-volumio volumio[3768]: Dload Upload Total Spent Left Speed May 25 19:54:40 kjellerstue-volumio volumio[3768]: [1001B blob data] May 25 19:54:40 kjellerstue-volumio volumio[3768]: retrying in 5 seconds, trial 0 May 25 19:54:40 kjellerstue-volumio volumio[3768]: info: Volumio Calling Home May 25 19:54:41 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. May 25 19:54:41 kjellerstue-volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:41 kjellerstue-volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:41 kjellerstue-volumio go-librespot[4046]: go-librespot daemon starting... May 25 19:54:41 kjellerstue-volumio go-librespot[4047]: time="2026-05-25T19:54:41+02:00" level=info msg="running go-librespot 0.4.0" May 25 19:54:41 kjellerstue-volumio go-librespot[4047]: time="2026-05-25T19:54:41+02:00" level=debug msg="app state loaded" May 25 19:54:41 kjellerstue-volumio go-librespot[4047]: time="2026-05-25T19:54:41+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 25 19:54:44 kjellerstue-volumio sudo[3950]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[3956]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[3959]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[4000]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[3960]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[4002]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[3986]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[4000]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 25 19:54:44 kjellerstue-volumio sudo[3960]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 25 19:54:44 kjellerstue-volumio sudo[4000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3960]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3998]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[3948]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:54:44 kjellerstue-volumio sudo[3948]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 25 19:54:44 kjellerstue-volumio sudo[3948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3950]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 25 19:54:44 kjellerstue-volumio sudo[3950]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3956]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service May 25 19:54:44 kjellerstue-volumio sudo[3956]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[4002]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 25 19:54:44 kjellerstue-volumio sudo[4002]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3959]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 25 19:54:44 kjellerstue-volumio sudo[3986]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 25 19:54:44 kjellerstue-volumio sudo[3986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3998]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 25 19:54:44 kjellerstue-volumio sudo[3959]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3998]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 25 19:54:44 kjellerstue-volumio sudo[3959]: pam_unix(sudo:session): session closed for user root May 25 19:54:44 kjellerstue-volumio sudo[3948]: pam_unix(sudo:session): session closed for user root May 25 19:54:44 kjellerstue-volumio volumio[3768]: info: MPD Permissions set May 25 19:54:44 kjellerstue-volumio volumio[3768]: info: MPD Permissions set May 25 19:54:44 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioGetState May 25 19:54:44 kjellerstue-volumio volumio[3768]: info: CorePlayQueue::getTrack 0 May 25 19:54:44 kjellerstue-volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 25 19:54:44 kjellerstue-volumio systemd[1]: Stopping mpd.service - Music Player Daemon... May 25 19:54:44 kjellerstue-volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 25 19:54:44 kjellerstue-volumio sudo[3956]: pam_unix(sudo:session): session closed for user root May 25 19:54:44 kjellerstue-volumio systemd[1]: shairport-sync.service: Deactivated successfully. May 25 19:54:44 kjellerstue-volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 25 19:54:44 kjellerstue-volumio systemd[1]: shairport-sync.service: Consumed 1.843s CPU time. May 25 19:54:44 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 25 19:54:44 kjellerstue-volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:44 kjellerstue-volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 25 19:54:44 kjellerstue-volumio go-librespot[4076]: go-librespot daemon starting... May 25 19:54:44 kjellerstue-volumio sudo[3986]: pam_unix(sudo:session): session closed for user root May 25 19:54:44 kjellerstue-volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 25 19:54:44 kjellerstue-volumio sudo[4000]: pam_unix(sudo:session): session closed for user root May 25 19:54:44 kjellerstue-volumio sudo[4002]: pam_unix(sudo:session): session closed for user root May 25 19:54:44 kjellerstue-volumio sudo[3998]: pam_unix(sudo:session): session closed for user root May 25 19:54:44 kjellerstue-volumio systemd[1]: mpd.service: Deactivated successfully. May 25 19:54:44 kjellerstue-volumio systemd[1]: Stopped mpd.service - Music Player Daemon. May 25 19:54:44 kjellerstue-volumio systemd[1]: mpd.service: Consumed 1.333s CPU time. May 25 19:54:44 kjellerstue-volumio volumio[3768]: info: Shairport-Sync Started May 25 19:54:44 kjellerstue-volumio volumio[3768]: Error adding Membership: Error: addMembership EINVAL May 25 19:54:44 kjellerstue-volumio go-librespot[4077]: time="2026-05-25T19:54:44+02:00" level=info msg="running go-librespot 0.4.0" May 25 19:54:44 kjellerstue-volumio volumio[3768]: info: Shairport-Sync Started May 25 19:54:44 kjellerstue-volumio volumio[3768]: info: Shairport-Sync Started May 25 19:54:44 kjellerstue-volumio go-librespot[4077]: time="2026-05-25T19:54:44+02:00" level=debug msg="app state loaded" May 25 19:54:44 kjellerstue-volumio go-librespot[4077]: time="2026-05-25T19:54:44+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 25 19:54:44 kjellerstue-volumio systemd[1]: mpd.socket: Deactivated successfully. May 25 19:54:44 kjellerstue-volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 25 19:54:44 kjellerstue-volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 25 19:54:44 kjellerstue-volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 25 19:54:44 kjellerstue-volumio systemd[1]: Starting mpd.service - Music Player Daemon... May 25 19:54:47 kjellerstue-volumio volumio[3768]: info: go-librespot daemon successfully initialized May 25 19:54:48 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 25 19:54:48 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 25 19:54:48 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 25 19:54:48 kjellerstue-volumio volumio[3768]: error: Plugin music_service mpd failed to complete 'onStart' in a timely fashion May 25 19:54:48 kjellerstue-volumio volumio[3768]: info: ------------------------------------------- May 25 19:54:48 kjellerstue-volumio volumio[3768]: info: ----- MyVolumio plugins startup ---- May 25 19:54:48 kjellerstue-volumio volumio[3768]: info: ------------------------------------------- May 25 19:54:48 kjellerstue-volumio volumio[3768]: info: [MyVolumio PluginManager] Fetching plans data.... May 25 19:54:50 kjellerstue-volumio volumio[3768]: info: Initializing connection to go-librespot Websocket May 25 19:54:50 kjellerstue-volumio go-librespot[4077]: time="2026-05-25T19:54:50+02:00" level=debug msg="new websocket client" May 25 19:54:50 kjellerstue-volumio volumio[3768]: info: Connection to go-librespot Websocket established May 25 19:54:52 kjellerstue-volumio key.dns_resolver[4042]: hall: No address associated with name May 25 19:54:53 kjellerstue-volumio volumio[3768]: info: Getting Spotify volume May 25 19:54:53 kjellerstue-volumio volumio[3768]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 May 25 19:54:53 kjellerstue-volumio volumio[3768]: info: CoreCommandRouter::volumioGetState May 25 19:54:53 kjellerstue-volumio volumio[3768]: info: CorePlayQueue::getTrack 0 May 25 19:55:00 kjellerstue-volumio go-librespot[4077]: time="2026-05-25T19:55:00+02: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" May 25 19:55:00 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 25 19:55:00 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 25 19:55:00 kjellerstue-volumio volumio[3768]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 25 19:55:00 kjellerstue-volumio volumio[3768]: Error: socket hang up May 25 19:55:00 kjellerstue-volumio volumio[3768]: at connResetException (node:internal/errors:720:14) May 25 19:55:00 kjellerstue-volumio volumio[3768]: at Socket.socketOnEnd (node:_http_client:519:23) May 25 19:55:00 kjellerstue-volumio volumio[3768]: at Socket.emit (node:events:526:35) May 25 19:55:00 kjellerstue-volumio volumio[3768]: at endReadableNT (node:internal/streams/readable:1376:12) May 25 19:55:00 kjellerstue-volumio volumio[3768]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { May 25 19:55:00 kjellerstue-volumio volumio[3768]: code: 'ECONNRESET', May 25 19:55:00 kjellerstue-volumio volumio[3768]: response: undefined May 25 19:55:00 kjellerstue-volumio volumio[3768]: } May 25 19:55:00 kjellerstue-volumio volumio[3768]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 25 19:55:01 kjellerstue-volumio dhcpcd[743]: eth0: offered 192.168.4.5 from 192.168.4.1 May 25 19:55:01 kjellerstue-volumio dhcpcd[743]: eth0: probing address 192.168.4.5/24 May 25 19:55:02 kjellerstue-volumio dhcpcd[652]: eth0: offered 192.168.4.5 from 192.168.4.1 May 25 19:55:02 kjellerstue-volumio dhcpcd[652]: eth0: probing address 192.168.4.5/24 May 25 19:55:03 kjellerstue-volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. May 25 19:55:03 kjellerstue-volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 25 19:55:03 kjellerstue-volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 25 19:55:03 kjellerstue-volumio go-librespot[4149]: go-librespot daemon starting... May 25 19:55:03 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:03+02:00" level=info msg="running go-librespot 0.4.0" May 25 19:55:03 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:03+02:00" level=debug msg="app state loaded" May 25 19:55:03 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:03+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 25 19:55:06 kjellerstue-volumio dhcpcd[743]: eth0: leased 192.168.4.5 for 86400 seconds May 25 19:55:06 kjellerstue-volumio avahi-daemon[662]: Registering new address record for 192.168.4.5 on eth0.IPv4. May 25 19:55:06 kjellerstue-volumio dhcpcd[743]: eth0: adding route to 192.168.4.0/24 May 25 19:55:06 kjellerstue-volumio dhcpcd[743]: eth0: changing default route via 192.168.4.1 May 25 19:55:06 kjellerstue-volumio dhcpcd[652]: eth0: pid 743 deleted default route May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... May 25 19:55:06 kjellerstue-volumio systemd[1]: welcome.service: Deactivated successfully. May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... May 25 19:55:06 kjellerstue-volumio avahi-daemon[662]: Withdrawing address record for 169.254.151.92 on eth0. May 25 19:55:06 kjellerstue-volumio avahi-daemon[662]: Leaving mDNS multicast group on interface eth0.IPv4 with address 169.254.151.92. May 25 19:55:06 kjellerstue-volumio dhcpcd[652]: eth0: pid 743 deleted IP address 169.254.151.92/16 May 25 19:55:06 kjellerstue-volumio avahi-daemon[662]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.4.5. May 25 19:55:06 kjellerstue-volumio dhcpcd[652]: eth0: deleting route to 169.254.0.0/16 May 25 19:55:06 kjellerstue-volumio dhcpcd[743]: eth0: deleting route to 169.254.0.0/16 May 25 19:55:06 kjellerstue-volumio dhcpcd[652]: eth0: probing for an IPv4LL address May 25 19:55:06 kjellerstue-volumio systemd[1]: Starting welcome.service - Show a welcome message on console... May 25 19:55:06 kjellerstue-volumio welcome[4175]: Resolved ip:[1] 192.168.4.5 May 25 19:55:06 kjellerstue-volumio systemd[1]: Finished welcome.service - Show a welcome message on console. May 25 19:55:06 kjellerstue-volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... May 25 19:55:06 kjellerstue-volumio systemd[1]: welcome.service: Deactivated successfully. May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. May 25 19:55:06 kjellerstue-volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... May 25 19:55:06 kjellerstue-volumio systemd[1]: Starting welcome.service - Show a welcome message on console... May 25 19:55:06 kjellerstue-volumio welcome[4215]: Resolved ip:[1] 192.168.4.5 May 25 19:55:06 kjellerstue-volumio systemd[1]: Finished welcome.service - Show a welcome message on console. May 25 19:55:06 kjellerstue-volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. May 25 19:55:07 kjellerstue-volumio dhcpcd[652]: eth0: leased 192.168.4.5 for 86400 seconds May 25 19:55:07 kjellerstue-volumio dhcpcd[652]: eth0: adding route to 192.168.4.0/24 May 25 19:55:07 kjellerstue-volumio dhcpcd[652]: eth0: adding default route via 192.168.4.1 May 25 19:55:07 kjellerstue-volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. May 25 19:55:07 kjellerstue-volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... May 25 19:55:07 kjellerstue-volumio systemd[1]: welcome.service: Deactivated successfully. May 25 19:55:07 kjellerstue-volumio systemd[1]: Stopped welcome.service - Show a welcome message on console. May 25 19:55:07 kjellerstue-volumio systemd[1]: Stopping welcome.service - Show a welcome message on console... May 25 19:55:07 kjellerstue-volumio systemd[1]: Starting welcome.service - Show a welcome message on console... May 25 19:55:07 kjellerstue-volumio welcome[4240]: Resolved ip:[1] 192.168.4.5 May 25 19:55:07 kjellerstue-volumio systemd[1]: Finished welcome.service - Show a welcome message on console. May 25 19:55:07 kjellerstue-volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. May 25 19:55:08 kjellerstue-volumio ntpd[1022]: IO: Listen normally on 5 eth0 192.168.4.5:123 May 25 19:55:08 kjellerstue-volumio ntpd[1022]: IO: Deleting interface #4 eth0, 169.254.151.92#123, interface stats: received=0, sent=22, dropped=0, active_time=3452 secs May 25 19:55:08 kjellerstue-volumio ntpd[1022]: PROTO: 192.36.143.130 unlink local addr 169.254.151.92 -> May 25 19:55:08 kjellerstue-volumio ntpd[1022]: PROTO: 195.72.61.39 unlink local addr 169.254.151.92 -> May 25 19:55:08 kjellerstue-volumio ntpd[1022]: PROTO: 162.159.200.123 unlink local addr 169.254.151.92 -> May 25 19:55:08 kjellerstue-volumio ntpd[1022]: PROTO: 185.41.243.43 unlink local addr 169.254.151.92 -> May 25 19:55:08 kjellerstue-volumio ntpd[1022]: PROTO: 193.150.22.36 unlink local addr 169.254.151.92 -> May 25 19:55:08 kjellerstue-volumio ntpd[1022]: PROTO: 77.95.79.99 unlink local addr 169.254.151.92 -> May 25 19:55:08 kjellerstue-volumio ntpd[1022]: PROTO: 185.175.56.208 unlink local addr 169.254.151.92 -> May 25 19:55:08 kjellerstue-volumio ntpd[1022]: IO: new interface(s) found: waking up resolver May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=info msg="zeroconf server listening on port 45173" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="obtained new client token: AACotGrsK1s1PyPQhfznC9Zzu5ERO9PeKCptuV/G/rlBhdsBDZpqebYjI2VpAOMtk/og+v6+3jDrnjVqMhq0hisIPLPKnZHleU/nZ3xa63mqLAqRqD+kPvEHN4Au0W9aVugC66n182gC7pvEQkxY/qeuX+HxieKVIk8gf7ttjPnHADxYQmxiV1rABPHVizniB+KP0KtbgYrjw6aXSZpphm61dY4pGXzJEZ5UUeZ++Mw8yFiNzO8aCc0=" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="completed keyexchange" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="completed challenge" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=info msg="authenticated AP" username="ro******er" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=info msg="authenticated Login5" username="ro******er" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="initializing zeroconf session" username="ro******er" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="dealer connection opened" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=trace msg="starting accesspoint recv loop" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=trace msg="starting dealer recv loop" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=trace msg="received accesspoint ping" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="received connection id: NmM4NDEwOGQtYWNj...MDZGRUI1Q0NGNQ==" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=trace msg="received accesspoint pong ack" May 25 19:55:09 kjellerstue-volumio key.dns_resolver[4118]: hall: No address associated with name May 25 19:55:09 kjellerstue-volumio kernel: CIFS: VFS: \\hall has not responded in 180 seconds. Reconnecting... May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="put connect state because NEW_DEVICE" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="update volume requested to 65535/65535" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=debug msg="put connect state because VOLUME_CHANGED" May 25 19:55:09 kjellerstue-volumio go-librespot[4150]: time="2026-05-25T19:55:09+02:00" level=trace msg="emitting websocket event: volume" May 25 19:55:10 kjellerstue-volumio sudo[4085]: root : unable to resolve host kjellerstue-volumio: System error May 25 19:55:10 kjellerstue-volumio sudo[4085]: sudo: unable to resolve host kjellerstue-volumio: System error May 25 19:55:10 kjellerstue-volumio sudo[4085]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 25 19:55:10 kjellerstue-volumio sudo[4085]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 25 19:55:10 kjellerstue-volumio sudo[4085]: pam_unix(sudo:session): session closed for user root May 25 19:55:11 kjellerstue-volumio mpd[4250]: 2026-05-25T19:55:11 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 25 19:55:11 kjellerstue-volumio systemd[1]: Started mpd.service - Music Player Daemon. May 25 19:55:11 kjellerstue-volumio sudo[3950]: pam_unix(sudo:session): session closed for user root May 25 19:55:11 kjellerstue-volumio sudo[3960]: pam_unix(sudo:session): session closed for user root May 25 19:55:16 kjellerstue-volumio sudo[4133]: volumio : unable to resolve host kjellerstue-volumio: System error May 25 19:55:16 kjellerstue-volumio sudo[4133]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-25 19:54' May 25 19:55:16 kjellerstue-volumio sudo[4133]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"