Jun 01 09:26:00 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:00.603-04:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Jun 01 09:26:00 volumio volumio-remote-updater[761]: [2026-06-01 09:26:00] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 01 09:26:00 volumio volumio-remote-updater[761]: [2026-06-01 09:26:00] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 01 09:26:00 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:00 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:00.606-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:26:00 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jun 01 09:26:00 volumio systemd[1]: volumio.service: Consumed 15.401s CPU time. Jun 01 09:26:00 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:26:00 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:26:00 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 34095. Jun 01 09:26:00 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:26:00 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jun 01 09:26:00 volumio systemd[1]: volumio.service: Consumed 15.401s CPU time. Jun 01 09:26:00 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jun 01 09:26:00 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:26:01 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:01.607-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:26:01 volumio ntpd[1016]: CLOCK: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): will expire in less than 27 days Jun 01 09:26:02 volumio volumio[26483]: info: ------------------------------------------- Jun 01 09:26:02 volumio volumio[26483]: info: ----- Volumio3 ---- Jun 01 09:26:02 volumio volumio[26483]: info: ------------------------------------------- Jun 01 09:26:02 volumio volumio[26483]: info: ----- System startup ---- Jun 01 09:26:02 volumio volumio[26483]: info: ------------------------------------------- Jun 01 09:26:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jun 01 09:26:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:02 volumio go-librespot[26504]: go-librespot daemon starting... Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="app state loaded" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:02 volumio volumio[26483]: info: MYVOLUMIO Environment detected Jun 01 09:26:02 volumio volumio[26483]: info: Plugin folders cleanup Jun 01 09:26:02 volumio volumio[26483]: info: Scanning into folder /volumio/app/plugins/ Jun 01 09:26:02 volumio volumio[26483]: info: Scanning category audio_interface Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:26:02 volumio volumio[26483]: info: Scanning category miscellanea Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=info msg="zeroconf server listening on port 33371" Jun 01 09:26:02 volumio volumio[26483]: info: Scanning category music_service Jun 01 09:26:02 volumio volumio[26483]: info: Scanning category plugins.json Jun 01 09:26:02 volumio volumio[26483]: info: Scanning category system_controller Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:02 volumio volumio[26483]: info: Scanning category user_interface Jun 01 09:26:02 volumio volumio[26483]: info: Scanning into folder /data/plugins/ Jun 01 09:26:02 volumio volumio[26483]: info: Scanning category music_service Jun 01 09:26:02 volumio volumio[26483]: info: Plugin folders cleanup completed Jun 01 09:26:02 volumio volumio[26483]: info: ------------------------------------------- Jun 01 09:26:02 volumio volumio[26483]: info: ----- Core plugins startup ---- Jun 01 09:26:02 volumio volumio[26483]: info: ------------------------------------------- Jun 01 09:26:02 volumio volumio[26483]: info: Loading plugins from folder /volumio/app/plugins/ Jun 01 09:26:02 volumio volumio[26483]: info: Adding plugin upnp to MyMusic Plugins Jun 01 09:26:02 volumio volumio[26483]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 01 09:26:02 volumio volumio[26483]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 01 09:26:02 volumio volumio[26483]: info: Loading plugins from folder /data/plugins/ Jun 01 09:26:02 volumio volumio[26483]: info: Loading plugin "system"... Jun 01 09:26:02 volumio volumio[26483]: info: Loading plugin "appearance"... Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="obtained new client token: AAB26DOq3KDR6FpbdrgeCzPdS2w4eICFfqJ+8XaKvLxI5QdZE9pgaOWHC5tDvQWNVHSA9IvSNdvf8JsWHRc7MlT+oejVFfsxxh/UqE2IwfpNGK/bvYAFQdH01ANJX2GtIGsG1xJX+Ijg9P7Mx0nOWLpEVVDH0bNm60BjPBPGdjafKBFXgJXtf/BbkJxgSKVZw+13cib8HaMWWAfMc6CBU1BRrN/+oduRtEfLBSLHvbqDPbwHnYTqxmWtyQ==" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=debug msg="completed challenge" Jun 01 09:26:02 volumio go-librespot[26505]: time="2026-06-01T09:26:02-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "network"... Jun 01 09:26:03 volumio volumio[26483]: info: Refreshing Cached IP Addresses Jun 01 09:26:03 volumio sudo[26521]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:26:03 volumio sudo[26521]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:03 volumio sudo[26521]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:03 volumio sudo[26523]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:26:03 volumio sudo[26523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "services"... Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "volumio5onboarding"... Jun 01 09:26:03 volumio sudo[26523]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "alsa_controller"... Jun 01 09:26:03 volumio sudo[26531]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 01 09:26:03 volumio sudo[26531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:03 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "wizard"... Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "networkfs"... Jun 01 09:26:03 volumio volumio[26483]: info: Starting Udev Watcher for removable devices Jun 01 09:26:03 volumio volumio[26483]: info: Ignoring mount for partition: boot Jun 01 09:26:03 volumio volumio[26483]: info: Ignoring mount for partition: volumio Jun 01 09:26:03 volumio volumio[26483]: info: Ignoring mount for partition: volumio_data Jun 01 09:26:03 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "volumio_command_line_client"... Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "upnp"... Jun 01 09:26:03 volumio volumio[26483]: info: [1780320363259] Starting Upmpd Daemon Jun 01 09:26:03 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "my_music"... Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "mpd"... Jun 01 09:26:03 volumio go-librespot[26505]: time="2026-06-01T09:26:03-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:03 volumio volumio[26483]: info: Loading plugin "upnp_browser"... Jun 01 09:26:03 volumio go-librespot[26505]: time="2026-06-01T09:26:03-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:03 volumio go-librespot[26505]: time="2026-06-01T09:26:03-04:00" level=debug msg="completed challenge" Jun 01 09:26:03 volumio go-librespot[26505]: time="2026-06-01T09:26:03-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:04 volumio go-librespot[26505]: time="2026-06-01T09:26:04-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:26:04 volumio go-librespot[26505]: time="2026-06-01T09:26:04-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:04 volumio go-librespot[26505]: time="2026-06-01T09:26:04-04:00" level=debug msg="completed challenge" Jun 01 09:26:04 volumio volumio[26483]: info: Starting UPNP Browser Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "alarm-clock"... Jun 01 09:26:04 volumio go-librespot[26505]: time="2026-06-01T09:26:04-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "airplay_emulation"... Jun 01 09:26:04 volumio volumio[26483]: info: Starting Shairport Sync Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "last_100"... Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "webradio"... Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "i2s_dacs"... Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "volumiodiscovery"... Jun 01 09:26:04 volumio volumio[26483]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:04 volumio volumio[26483]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:04 volumio volumio[26483]: *** WARNING *** For more information see Jun 01 09:26:04 volumio volumio[26483]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:04 volumio volumio[26483]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:04 volumio node[26483]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:04 volumio volumio[26483]: *** WARNING *** For more information see Jun 01 09:26:04 volumio node[26483]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:04 volumio node[26483]: *** WARNING *** For more information see Jun 01 09:26:04 volumio node[26483]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:04 volumio node[26483]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:04 volumio node[26483]: *** WARNING *** For more information see Jun 01 09:26:04 volumio volumio[26483]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 01 09:26:04 volumio volumio[26483]: info: Discovery: Started advertising with name: Volumio Jun 01 09:26:04 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "spop"... Jun 01 09:26:04 volumio go-librespot[26505]: time="2026-06-01T09:26:04-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "outputs"... Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "albumart"... Jun 01 09:26:04 volumio volumio[26483]: info: Plugin example_plugin is not enabled Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "inputs"... Jun 01 09:26:04 volumio volumio[26483]: info: Loading plugin "updater_comm"... Jun 01 09:26:05 volumio volumio[26483]: info: Plugin mpdemulation is not enabled Jun 01 09:26:05 volumio volumio[26483]: info: Loading plugin "rest_api"... Jun 01 09:26:05 volumio volumio[26483]: info: Loading plugin "websocket"... Jun 01 09:26:05 volumio volumio[26483]: info: Starting Socket.io Server version 1.7.4 Jun 01 09:26:05 volumio volumio[26483]: info: Loading i18n strings for locale en Jun 01 09:26:05 volumio volumio[26483]: Updating browse sources language Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::initPlayerControls Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:05 volumio go-librespot[26505]: time="2026-06-01T09:26:05-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:05 volumio go-librespot[26505]: time="2026-06-01T09:26:05-04:00" level=debug msg="completed challenge" Jun 01 09:26:05 volumio volumio[26483]: Express server listening on port 3000 Jun 01 09:26:05 volumio volumio[26483]: [Metrics] WebUI: 3s 427.13ms Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::resetVolumioState Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::getcurrentVolume Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:26:05 volumio volumio[26483]: info: Volumio Network Manager: Network status updated: 1 Jun 01 09:26:05 volumio volumio[26483]: 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 Jun 01 09:26:05 volumio volumio[26556]: Forking 3 albumart workers Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: Reloading queue from file Jun 01 09:26:05 volumio volumio[26483]: 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 Jun 01 09:26:05 volumio volumio[26483]: info: Setting Device type: Raspberry PI Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::setRepeat null single undefined Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::pushState Jun 01 09:26:05 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::setRandom null Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::pushState Jun 01 09:26:05 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:05 volumio volumio[26483]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jun 01 09:26:05 volumio volumio[26483]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Jun 01 09:26:05 volumio volumio[26483]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jun 01 09:26:05 volumio go-librespot[26505]: time="2026-06-01T09:26:05-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:05 volumio volumio[26483]: info: Completed loading Core Plugins Jun 01 09:26:05 volumio volumio[26483]: info: Preparing to generate the ALSA configuration file Jun 01 09:26:05 volumio volumio[26483]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::pushState Jun 01 09:26:05 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:05 volumio volumio[26483]: info: CoreStateMachine::updateTrackBlock Jun 01 09:26:05 volumio volumio[26483]: info: CorePlayQueue::getTrackBlock Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:26:05 volumio volumio[26483]: 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 Jun 01 09:26:05 volumio volumio[26483]: 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 Jun 01 09:26:05 volumio volumio[26483]: info: Asound.conf file unchanged, so no further update is needed Jun 01 09:26:05 volumio volumio[26483]: info: Output device has changed, restarting MPD Jun 01 09:26:05 volumio volumio[26483]: info: Output device has changed, restarting Shairport Sync Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:05 volumio sudo[26614]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:26:05 volumio sudo[26614]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:05 volumio sudo[26613]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:26:05 volumio sudo[26613]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:05 volumio sudo[26613]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:05 volumio volumio[26483]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:05 volumio volumio[26483]: info: ___________ START PLUGINS ___________ Jun 01 09:26:05 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jun 01 09:26:05 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 01 09:26:05 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 09:26:05 volumio systemd[1]: mpd.service: Consumed 1.957s CPU time. Jun 01 09:26:05 volumio volumio[26483]: info: ControllerMpd::onStart: Initializing MPD Jun 01 09:26:05 volumio volumio[26483]: info: Creating MPD Configuration file Jun 01 09:26:05 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 01 09:26:05 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 09:26:05 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 09:26:05 volumio volumio-remote-updater[761]: [2026-06-01 09:26:05] [connect] Successful connection Jun 01 09:26:05 volumio sudo[26622]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:05 volumio sudo[26625]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:26:05 volumio volumio[26483]: info: [1780320365630] CoreMusicLibrary::Adding element Media Servers Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:05 volumio sudo[26625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:05 volumio sudo[26622]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:05 volumio sudo[26625]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:05 volumio volumio[26483]: info: UPNP Browser: Client initialized successfully Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:05 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 09:26:05 volumio sudo[26627]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:26:05 volumio sudo[26627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:05 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 09:26:05 volumio sudo[26622]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:05 volumio volumio[26483]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:05 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:05 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 09:26:05 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 01 09:26:05 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 09:26:05 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 09:26:05 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 09:26:05 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 09:26:05 volumio volumio[26483]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:05 volumio volumio[26483]: info: [1780320365741] CoreMusicLibrary::Adding element Last_100 Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:05 volumio volumio[26483]: info: [1780320365748] CoreMusicLibrary::Adding element Webradio Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:05 volumio volumio[26483]: info: Initializing BBC Radios Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:05 volumio sudo[26641]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 09:26:05 volumio sudo[26641]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 01 09:26:05 volumio volumio[26483]: info: Creating Spotify config file Jun 01 09:26:05 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:05 volumio sudo[26641]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:05 volumio go-librespot[26505]: time="2026-06-01T09:26:05-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jun 01 09:26:06 volumio go-librespot[26505]: time="2026-06-01T09:26:06-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:06 volumio go-librespot[26505]: time="2026-06-01T09:26:06-04:00" level=debug msg="completed challenge" Jun 01 09:26:06 volumio go-librespot[26505]: time="2026-06-01T09:26:06-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:06 volumio sudo[26531]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:06 volumio volumio[26483]: info: Volumio Calling Home Jun 01 09:26:06 volumio volumio[26574]: Starting albumart workers Jun 01 09:26:06 volumio volumio[26576]: Starting albumart workers Jun 01 09:26:06 volumio volumio[26573]: Starting albumart workers Jun 01 09:26:06 volumio volumio[26483]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:26:06 volumio volumio[26483]: info: CoreStateMachine::pushState Jun 01 09:26:06 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:06 volumio volumio[26483]: info: Discovery: adding 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:26:06 volumio volumio[26483]: info: Discovery: Found device Volumio Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:06 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:06 volumio volumio[26483]: 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 Jun 01 09:26:06 volumio volumio[26483]: info: MPD Permissions set Jun 01 09:26:06 volumio volumio[26483]: info: MPD Permissions set Jun 01 09:26:06 volumio volumio[26483]: info: Discovery: this is already registered, 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:26:06 volumio volumio[26483]: info: Discovery: Found device Volumio Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:06 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:06 volumio volumio-remote-updater[761]: [2026-06-01 09:26:06] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1780320365 101 Jun 01 09:26:06 volumio go-librespot[26505]: time="2026-06-01T09:26:06-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:26:06 volumio volumio[26483]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jun 01 09:26:06 volumio volumio[26483]: info: Volumio called home Jun 01 09:26:06 volumio volumio[26483]: info: Spotify config file written Jun 01 09:26:06 volumio volumio[26483]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 01 09:26:06 volumio sudo[26661]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 01 09:26:06 volumio sudo[26661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio go-librespot[26505]: time="2026-06-01T09:26:06-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:06 volumio go-librespot[26505]: time="2026-06-01T09:26:06-04:00" level=debug msg="completed challenge" Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jun 01 09:26:06 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jun 01 09:26:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:06 volumio go-librespot[26666]: go-librespot daemon starting... Jun 01 09:26:06 volumio sudo[26661]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:06 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:06 volumio go-librespot[26677]: time="2026-06-01T09:26:06-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:06 volumio go-librespot[26677]: time="2026-06-01T09:26:06-04:00" level=debug msg="app state loaded" Jun 01 09:26:06 volumio volumio[26483]: info: No need to fix Spotify hosts Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:07 volumio volumio[26483]: 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: 3 Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=info msg="zeroconf server listening on port 39497" Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:07 volumio volumio[26483]: 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: 3 Jun 01 09:26:07 volumio volumio[26483]: info: Starting Shairport Sync Jun 01 09:26:07 volumio volumio[26483]: info: Starting Shairport Sync Jun 01 09:26:07 volumio volumio[26483]: info: Starting Shairport Sync Jun 01 09:26:07 volumio sudo[26702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:07 volumio sudo[26702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:07 volumio sudo[26704]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:07 volumio sudo[26704]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:07 volumio sudo[26707]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:07 volumio sudo[26707]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:07 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 01 09:26:07 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 01 09:26:07 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:07 volumio systemd[1]: shairport-sync.service: Consumed 1.615s CPU time. Jun 01 09:26:07 volumio volumio[26483]: info: New Spotify access tokenBQCZNHVZj9... Jun 01 09:26:07 volumio volumio[26483]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 01 09:26:07 volumio volumio[26483]: 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: 3 Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=debug msg="obtained new client token: AAAdMZf/khC4tRODbI8CcR0/aMDTroZUMIaN8JZ7fBMJOd+U2NaN3NCY8yLCQIfBU7f4iFptusIQT7OpBgoOSwgX3+o5zizkH4FoDe7LMkTlOwDHapA25yjh1LAbby2PeZPaGXrI66HyT2vOoC7ti+qqYP6Xwilc2WAtk4uEj1C4kwz33KiLKn5uRQcaunf9OHQRKJ7DeuhFR7X1zXkVmZgrCAxy1uYynTJ85Maeub6qo/eS4IYCR3Y6kg==" Jun 01 09:26:07 volumio volumio[26483]: 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: 3 Jun 01 09:26:07 volumio volumio[26483]: info: Received Get System Info Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 09:26:07 volumio volumio[26483]: info: Discovery: Getting this device information Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:07 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:07 volumio volumio[26483]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:07 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:07 volumio sudo[26702]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:07 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 01 09:26:07 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 01 09:26:07 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:07 volumio volumio[26483]: info: Shairport-Sync Started Jun 01 09:26:07 volumio volumio[26483]: Error adding Membership: Error: addMembership EINVAL Jun 01 09:26:07 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:07 volumio sudo[26704]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:07 volumio sudo[26707]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:07 volumio volumio[26483]: info: Shairport-Sync Started Jun 01 09:26:07 volumio volumio[26483]: info: Shairport-Sync Started Jun 01 09:26:07 volumio volumio[26483]: SPOTIFY: User informations: {"account_id":"W4wCmVA8pZ","country":"US","display_name":"122559042","email":"jarrod@higginscomputer.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/122559042"},"followers":{"href":null,"total":3},"href":"https://api.spotify.com/v1/users/122559042","id":"122559042","images":[],"product":"premium","type":"user","uri":"spotify:user:122559042"} Jun 01 09:26:07 volumio volumio[26483]: info: Spotify Successfully logged in Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:07 volumio volumio[26483]: info: [1780320367668] CoreMusicLibrary::Adding element Spotify Jun 01 09:26:07 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:07 volumio volumio[26483]: Cannot find translation for source Spotify Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=debug msg="completed challenge" Jun 01 09:26:07 volumio go-librespot[26677]: time="2026-06-01T09:26:07-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:07 volumio mpd[26656]: 2026-06-01T09:26:07 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 01 09:26:07 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jun 01 09:26:07 volumio sudo[26614]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:07 volumio sudo[26627]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:07 volumio volumio[26483]: info: Completed starting Core Plugins Jun 01 09:26:07 volumio volumio[26483]: info: ------------------------------------------- Jun 01 09:26:07 volumio volumio[26483]: info: ----- MyVolumio plugins startup ---- Jun 01 09:26:07 volumio volumio[26483]: info: ------------------------------------------- Jun 01 09:26:07 volumio volumio[26483]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 01 09:26:07 volumio volumio[26483]: error: MPD error: The expression evaluated to a falsy value: Jun 01 09:26:07 volumio volumio[26483]: assert.ok(self.idling) Jun 01 09:26:07 volumio volumio[26483]: error: The expression evaluated to a falsy value: Jun 01 09:26:07 volumio volumio[26483]: assert.ok(self.idling) Jun 01 09:26:07 volumio volumio[26483]: info: MPD running with PID26656 Jun 01 09:26:07 volumio volumio[26483]: ,establishing connection Jun 01 09:26:07 volumio volumio[26483]: error: updateQueue error: null Jun 01 09:26:07 volumio volumio[26483]: error: updateQueue error: null Jun 01 09:26:08 volumio go-librespot[26677]: time="2026-06-01T09:26:08-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:08 volumio go-librespot[26677]: time="2026-06-01T09:26:08-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:08 volumio go-librespot[26677]: time="2026-06-01T09:26:08-04:00" level=debug msg="completed challenge" Jun 01 09:26:08 volumio go-librespot[26677]: time="2026-06-01T09:26:08-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:09 volumio go-librespot[26677]: time="2026-06-01T09:26:09-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:26:09 volumio go-librespot[26677]: time="2026-06-01T09:26:09-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:09 volumio go-librespot[26677]: time="2026-06-01T09:26:09-04:00" level=debug msg="completed challenge" Jun 01 09:26:09 volumio go-librespot[26677]: time="2026-06-01T09:26:09-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:09 volumio go-librespot[26677]: time="2026-06-01T09:26:09-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:26:10 volumio go-librespot[26677]: time="2026-06-01T09:26:10-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:10 volumio go-librespot[26677]: time="2026-06-01T09:26:10-04:00" level=debug msg="completed challenge" Jun 01 09:26:10 volumio go-librespot[26677]: time="2026-06-01T09:26:10-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:10 volumio volumio[26483]: info: go-librespot daemon successfully initialized Jun 01 09:26:10 volumio go-librespot[26677]: time="2026-06-01T09:26:10-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jun 01 09:26:10 volumio go-librespot[26677]: time="2026-06-01T09:26:10-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:10 volumio go-librespot[26677]: time="2026-06-01T09:26:10-04:00" level=debug msg="completed challenge" Jun 01 09:26:10 volumio go-librespot[26677]: time="2026-06-01T09:26:10-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:11 volumio go-librespot[26677]: time="2026-06-01T09:26:11-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:26:11 volumio go-librespot[26677]: time="2026-06-01T09:26:11-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:11 volumio go-librespot[26677]: time="2026-06-01T09:26:11-04:00" level=debug msg="completed challenge" Jun 01 09:26:11 volumio go-librespot[26677]: time="2026-06-01T09:26:11-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:11 volumio go-librespot[26677]: time="2026-06-01T09:26:11-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:26:12 volumio volumio[26483]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 01 09:26:13 volumio sudo[26746]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:26:13 volumio sudo[26746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:13 volumio sudo[26746]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:13 volumio sudo[26748]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:26:13 volumio sudo[26748]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:13 volumio sudo[26748]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:13 volumio volumio[26483]: info: Initializing connection to go-librespot Websocket Jun 01 09:26:13 volumio sudo[26751]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 01 09:26:13 volumio sudo[26751]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:13 volumio volumio[26483]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 09:26:13 volumio sudo[26751]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:13 volumio volumio[26483]: info: Upmpdcli Daemon Started Jun 01 09:26:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jun 01 09:26:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:14 volumio go-librespot[26754]: go-librespot daemon starting... Jun 01 09:26:14 volumio go-librespot[26755]: time="2026-06-01T09:26:14-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:14 volumio go-librespot[26755]: time="2026-06-01T09:26:14-04:00" level=debug msg="app state loaded" Jun 01 09:26:14 volumio go-librespot[26755]: time="2026-06-01T09:26:14-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=info msg="zeroconf server listening on port 44205" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=debug msg="obtained new client token: AAAlNNbbYqg7YPSkj8c5q8Esn3zVDMk3fyU7Cgds117PWGxaPGcO24M1ckWdPDf6j3lx+1MKsGfpuGyP/MQl3ZzarTMQ/+Jw1jEwmqS1UReEX5wQ4eD5+KVGKzAQWDbfVKlTvsgLhpM5Y9yyp72rbOVAwIpz4sqHhjrOFoqHxaHBgcAeYcZgZAtyXjYfzKERsb9h+AmQYBlZSGs6Gnmhh5yu+fm7DdkmS4N4zN2GqW5JR0jEMJwI6VDl9w==" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=debug msg="completed challenge" Jun 01 09:26:15 volumio go-librespot[26755]: time="2026-06-01T09:26:15-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=debug msg="completed challenge" Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 01 09:26:16 volumio volumio[26483]: info: Adding plugin bluetooth to MyMusic Plugins Jun 01 09:26:16 volumio volumio[26483]: info: Adding plugin multiroom to MyMusic Plugins Jun 01 09:26:16 volumio volumio[26483]: info: Adding plugin metavolumio to MyMusic Plugins Jun 01 09:26:16 volumio volumio[26483]: info: Adding plugin cd_controller to MyMusic Plugins Jun 01 09:26:16 volumio volumio[26483]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 01 09:26:16 volumio volumio[26483]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 01 09:26:16 volumio volumio[26483]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 01 09:26:16 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:16 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:16 volumio volumio[26483]: info: Starting MyVolumio Remote Streaming Endpoints Jun 01 09:26:16 volumio volumio[26483]: info: MyVolumio login type: Token Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 01 09:26:16 volumio volumio[26483]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=debug msg="completed challenge" Jun 01 09:26:16 volumio go-librespot[26755]: time="2026-06-01T09:26:16-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:17 volumio volumio[26483]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 01 09:26:17 volumio volumio[26483]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 01 09:26:17 volumio volumio[26483]: info: Streaming services startup Jun 01 09:26:17 volumio volumio[26483]: info: Starting Streaming Daemon Jun 01 09:26:17 volumio sudo[26765]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:26:17 volumio sudo[26765]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:17 volumio volumio[26483]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 01 09:26:17 volumio sudo[26765]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:17 volumio volumio[26483]: info: Initializing connection to go-librespot Websocket Jun 01 09:26:17 volumio volumio[26483]: error: Cannot start Volumio Streaming Daemon Jun 01 09:26:17 volumio volumio[26483]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:26:17 volumio volumio[26483]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:26:17 volumio go-librespot[26755]: time="2026-06-01T09:26:17-04:00" level=debug msg="new websocket client" Jun 01 09:26:17 volumio volumio[26483]: info: Connection to go-librespot Websocket established Jun 01 09:26:17 volumio go-librespot[26755]: time="2026-06-01T09:26:17-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jun 01 09:26:17 volumio go-librespot[26755]: time="2026-06-01T09:26:17-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:17 volumio go-librespot[26755]: time="2026-06-01T09:26:17-04:00" level=debug msg="completed challenge" Jun 01 09:26:17 volumio go-librespot[26755]: time="2026-06-01T09:26:17-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:17 volumio volumio[26483]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 01 09:26:18 volumio go-librespot[26755]: time="2026-06-01T09:26:18-04:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jun 01 09:26:18 volumio go-librespot[26755]: time="2026-06-01T09:26:18-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:18 volumio go-librespot[26755]: time="2026-06-01T09:26:18-04:00" level=debug msg="completed challenge" Jun 01 09:26:18 volumio volumio[26483]: info: MyVolumio token set successfully Jun 01 09:26:18 volumio volumio[26483]: info: MYVOLUMIO: Adding device Jun 01 09:26:18 volumio volumio[26483]: info: MYVOLUMIO: Evaluating Server Jun 01 09:26:18 volumio go-librespot[26755]: time="2026-06-01T09:26:18-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:18 volumio volumio[26483]: info: MyVolumio status changed Jun 01 09:26:18 volumio volumio[26483]: info: Streaming services startup Jun 01 09:26:18 volumio volumio[26483]: info: Starting Streaming Daemon Jun 01 09:26:18 volumio volumio[26483]: info: Removing browser output: myVolumio user plan is not superstar Jun 01 09:26:18 volumio volumio[26483]: info: Removing audio output: Jun 01 09:26:18 volumio volumio[26483]: info: Stoppping Tunnel 1 Jun 01 09:26:18 volumio sudo[26792]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:26:18 volumio sudo[26792]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:18 volumio sudo[26794]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jun 01 09:26:18 volumio sudo[26794]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:18 volumio sudo[26792]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:18 volumio volumio[26483]: error: Cannot start Volumio Streaming Daemon Jun 01 09:26:18 volumio volumio[26483]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:26:18 volumio volumio[26483]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:26:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:18 volumio sudo[26794]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:18 volumio volumio[26483]: info: Remote SSH Stopped Jun 01 09:26:18 volumio volumio[26483]: info: Setting Geolocation for MyVolumio to us1 Jun 01 09:26:18 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:18 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:18 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:19 volumio go-librespot[26755]: time="2026-06-01T09:26:19-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:26:19 volumio go-librespot[26755]: time="2026-06-01T09:26:19-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:19 volumio go-librespot[26755]: time="2026-06-01T09:26:19-04:00" level=debug msg="completed challenge" Jun 01 09:26:19 volumio go-librespot[26755]: time="2026-06-01T09:26:19-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:19 volumio go-librespot[26755]: time="2026-06-01T09:26:19-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:26:19 volumio volumio[26483]: info: Connection to go-librespot Websocket closed Jun 01 09:26:19 volumio volumio[26483]: info: Successfully Added MyVolumio device Jun 01 09:26:19 volumio volumio[26483]: info: Updating MyVolumio device info Jun 01 09:26:19 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:19 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:19 volumio volumio[26483]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:20 volumio volumio[26483]: info: Getting Spotify volume Jun 01 09:26:20 volumio volumio[26483]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:26:20 volumio volumio[26483]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 09:26:20 volumio volumio[26483]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jun 01 09:26:20 volumio volumio[26483]: errno: -111, Jun 01 09:26:20 volumio volumio[26483]: code: 'ECONNREFUSED', Jun 01 09:26:20 volumio volumio[26483]: syscall: 'connect', Jun 01 09:26:20 volumio volumio[26483]: address: '127.0.0.1', Jun 01 09:26:20 volumio volumio[26483]: port: 9879, Jun 01 09:26:20 volumio volumio[26483]: response: undefined Jun 01 09:26:20 volumio volumio[26483]: } Jun 01 09:26:20 volumio volumio[26483]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:26:20 volumio sudo[26811]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-01 09:25' Jun 01 09:26:20 volumio sudo[26811]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:20 volumio sudo[26811]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jun 01 09:26:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:22 volumio go-librespot[26819]: go-librespot daemon starting... Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="app state loaded" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=info msg="zeroconf server listening on port 34665" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="obtained new client token: AACgqSnoEKXFOf2r0cm34QDaaOn5IZtT+o88bnSij3Ie46WJYFM/VTxfXFmBzpKVQWJ/cAFTUuOq4BPMb3gV0aICFxHn4yRuYAdlx8ZurFm5LA4M4+V6zgscJaWFeJq2b3seOLavbD/xJr2NOrXQ9DyUTgDGJ4S9Si6zxPTNs+rwhe6vj/A6+dUKf5/+1PFpE7PdkS8w03JONkw1UsjNItmt9a1Uq0NtHAIal/DKMeSd77PKn2AZgL1gxg==" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:22 volumio go-librespot[26820]: time="2026-06-01T09:26:22-04:00" level=debug msg="completed challenge" Jun 01 09:26:23 volumio go-librespot[26820]: time="2026-06-01T09:26:23-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:23 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:23.401-04:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Jun 01 09:26:23 volumio volumio-remote-updater[761]: [2026-06-01 09:26:23] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 01 09:26:23 volumio volumio-remote-updater[761]: [2026-06-01 09:26:23] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 01 09:26:23 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:23 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:23.405-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:26:23 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jun 01 09:26:23 volumio systemd[1]: volumio.service: Consumed 15.613s CPU time. Jun 01 09:26:23 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:26:23 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:26:23 volumio go-librespot[26820]: time="2026-06-01T09:26:23-04:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:443, retrying with a different AP" error="dial tcp 104.154.127.247:443: connect: connection refused" Jun 01 09:26:23 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 34096. Jun 01 09:26:23 volumio go-librespot[26820]: time="2026-06-01T09:26:23-04:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:80, retrying with a different AP" error="dial tcp 104.154.127.247:80: connect: connection refused" Jun 01 09:26:23 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:26:23 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jun 01 09:26:23 volumio systemd[1]: volumio.service: Consumed 15.613s CPU time. Jun 01 09:26:23 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jun 01 09:26:23 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:26:23 volumio go-librespot[26820]: time="2026-06-01T09:26:23-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:26:24 volumio go-librespot[26820]: time="2026-06-01T09:26:24-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:24 volumio go-librespot[26820]: time="2026-06-01T09:26:24-04:00" level=debug msg="completed challenge" Jun 01 09:26:24 volumio go-librespot[26820]: time="2026-06-01T09:26:24-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:24 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:24.407-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:26:24 volumio volumio[26850]: info: ------------------------------------------- Jun 01 09:26:24 volumio volumio[26850]: info: ----- Volumio3 ---- Jun 01 09:26:24 volumio volumio[26850]: info: ------------------------------------------- Jun 01 09:26:24 volumio volumio[26850]: info: ----- System startup ---- Jun 01 09:26:24 volumio volumio[26850]: info: ------------------------------------------- Jun 01 09:26:24 volumio go-librespot[26820]: time="2026-06-01T09:26:24-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jun 01 09:26:25 volumio go-librespot[26820]: time="2026-06-01T09:26:25-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:25 volumio go-librespot[26820]: time="2026-06-01T09:26:25-04:00" level=debug msg="completed challenge" Jun 01 09:26:25 volumio go-librespot[26820]: time="2026-06-01T09:26:25-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:25 volumio volumio[26850]: info: MYVOLUMIO Environment detected Jun 01 09:26:25 volumio volumio[26850]: info: Plugin folders cleanup Jun 01 09:26:25 volumio volumio[26850]: info: Scanning into folder /volumio/app/plugins/ Jun 01 09:26:25 volumio volumio[26850]: info: Scanning category audio_interface Jun 01 09:26:25 volumio volumio[26850]: info: Scanning category miscellanea Jun 01 09:26:25 volumio volumio[26850]: info: Scanning category music_service Jun 01 09:26:25 volumio volumio[26850]: info: Scanning category plugins.json Jun 01 09:26:25 volumio volumio[26850]: info: Scanning category system_controller Jun 01 09:26:25 volumio volumio[26850]: info: Scanning category user_interface Jun 01 09:26:25 volumio volumio[26850]: info: Scanning into folder /data/plugins/ Jun 01 09:26:25 volumio volumio[26850]: info: Scanning category music_service Jun 01 09:26:25 volumio volumio[26850]: info: Plugin folders cleanup completed Jun 01 09:26:25 volumio volumio[26850]: info: ------------------------------------------- Jun 01 09:26:25 volumio volumio[26850]: info: ----- Core plugins startup ---- Jun 01 09:26:25 volumio volumio[26850]: info: ------------------------------------------- Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugins from folder /volumio/app/plugins/ Jun 01 09:26:25 volumio volumio[26850]: info: Adding plugin upnp to MyMusic Plugins Jun 01 09:26:25 volumio volumio[26850]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 01 09:26:25 volumio volumio[26850]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugins from folder /data/plugins/ Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "system"... Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "appearance"... Jun 01 09:26:25 volumio go-librespot[26820]: time="2026-06-01T09:26:25-04:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jun 01 09:26:25 volumio go-librespot[26820]: time="2026-06-01T09:26:25-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.40.94:58282->104.199.65.9:80: read: connection reset by peer" Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "network"... Jun 01 09:26:25 volumio volumio[26850]: info: Refreshing Cached IP Addresses Jun 01 09:26:25 volumio sudo[26878]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:26:25 volumio sudo[26878]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:25 volumio sudo[26880]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:26:25 volumio sudo[26880]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "services"... Jun 01 09:26:25 volumio sudo[26878]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "volumio5onboarding"... Jun 01 09:26:25 volumio sudo[26880]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:25 volumio sudo[26887]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "alsa_controller"... Jun 01 09:26:25 volumio sudo[26887]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:25 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "wizard"... Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "networkfs"... Jun 01 09:26:25 volumio volumio[26850]: info: Starting Udev Watcher for removable devices Jun 01 09:26:25 volumio volumio[26850]: info: Ignoring mount for partition: boot Jun 01 09:26:25 volumio volumio[26850]: info: Ignoring mount for partition: volumio Jun 01 09:26:25 volumio volumio[26850]: info: Ignoring mount for partition: volumio_data Jun 01 09:26:25 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "volumio_command_line_client"... Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "upnp"... Jun 01 09:26:25 volumio volumio[26850]: info: [1780320385985] Starting Upmpd Daemon Jun 01 09:26:25 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "my_music"... Jun 01 09:26:25 volumio volumio[26850]: info: Loading plugin "mpd"... Jun 01 09:26:26 volumio volumio[26850]: info: Loading plugin "upnp_browser"... Jun 01 09:26:26 volumio go-librespot[26820]: time="2026-06-01T09:26:26-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:26 volumio go-librespot[26820]: time="2026-06-01T09:26:26-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:26 volumio go-librespot[26820]: time="2026-06-01T09:26:26-04:00" level=debug msg="completed challenge" Jun 01 09:26:26 volumio go-librespot[26820]: time="2026-06-01T09:26:26-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:26 volumio volumio[26850]: info: Starting UPNP Browser Jun 01 09:26:26 volumio volumio[26850]: info: Loading plugin "alarm-clock"... Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "airplay_emulation"... Jun 01 09:26:27 volumio volumio[26850]: info: Starting Shairport Sync Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "last_100"... Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "webradio"... Jun 01 09:26:27 volumio go-librespot[26820]: time="2026-06-01T09:26:27-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "i2s_dacs"... Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "volumiodiscovery"... Jun 01 09:26:27 volumio volumio[26850]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:27 volumio volumio[26850]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:27 volumio volumio[26850]: *** WARNING *** For more information see Jun 01 09:26:27 volumio volumio[26850]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:27 volumio volumio[26850]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:27 volumio volumio[26850]: *** WARNING *** For more information see Jun 01 09:26:27 volumio volumio[26850]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 01 09:26:27 volumio node[26850]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:27 volumio node[26850]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:27 volumio node[26850]: *** WARNING *** For more information see Jun 01 09:26:27 volumio node[26850]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:27 volumio node[26850]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:27 volumio node[26850]: *** WARNING *** For more information see Jun 01 09:26:27 volumio volumio[26850]: info: Discovery: Started advertising with name: Volumio Jun 01 09:26:27 volumio go-librespot[26820]: time="2026-06-01T09:26:27-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:27 volumio go-librespot[26820]: time="2026-06-01T09:26:27-04:00" level=debug msg="completed challenge" Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "spop"... Jun 01 09:26:27 volumio go-librespot[26820]: time="2026-06-01T09:26:27-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:27 volumio go-librespot[26820]: time="2026-06-01T09:26:27-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "outputs"... Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "albumart"... Jun 01 09:26:27 volumio volumio[26850]: info: Plugin example_plugin is not enabled Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "inputs"... Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "updater_comm"... Jun 01 09:26:27 volumio volumio[26850]: info: Plugin mpdemulation is not enabled Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "rest_api"... Jun 01 09:26:27 volumio volumio[26850]: info: Loading plugin "websocket"... Jun 01 09:26:27 volumio volumio[26850]: info: Starting Socket.io Server version 1.7.4 Jun 01 09:26:27 volumio volumio[26850]: info: Loading i18n strings for locale en Jun 01 09:26:27 volumio volumio[26850]: Updating browse sources language Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::initPlayerControls Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:27 volumio volumio[26850]: Express server listening on port 3000 Jun 01 09:26:27 volumio volumio[26850]: [Metrics] WebUI: 3s 397.69ms Jun 01 09:26:27 volumio volumio[26850]: info: CoreStateMachine::resetVolumioState Jun 01 09:26:27 volumio volumio[26850]: info: CoreStateMachine::getcurrentVolume Jun 01 09:26:27 volumio volumio[26850]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:26:27 volumio volumio[26850]: info: Volumio Network Manager: Network status updated: 1 Jun 01 09:26:27 volumio volumio[26850]: 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 Jun 01 09:26:27 volumio volumio[26913]: Forking 3 albumart workers Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:28 volumio volumio[26850]: info: Reloading queue from file Jun 01 09:26:28 volumio volumio[26850]: 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 Jun 01 09:26:28 volumio volumio[26850]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:26:28 volumio volumio[26850]: info: CoreStateMachine::pushState Jun 01 09:26:28 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:28 volumio volumio[26850]: info: CoreStateMachine::updateTrackBlock Jun 01 09:26:28 volumio volumio[26850]: info: CorePlayQueue::getTrackBlock Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:26:28 volumio volumio[26850]: info: CoreStateMachine::setRepeat null single undefined Jun 01 09:26:28 volumio volumio[26850]: info: CoreStateMachine::pushState Jun 01 09:26:28 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:28 volumio volumio[26850]: info: CoreStateMachine::setRandom null Jun 01 09:26:28 volumio volumio[26850]: info: CoreStateMachine::pushState Jun 01 09:26:28 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:28 volumio volumio[26850]: info: Setting Device type: Raspberry PI Jun 01 09:26:28 volumio volumio[26850]: info: Completed loading Core Plugins Jun 01 09:26:28 volumio volumio[26850]: info: Preparing to generate the ALSA configuration file Jun 01 09:26:28 volumio volumio[26850]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jun 01 09:26:28 volumio volumio[26850]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Jun 01 09:26:28 volumio volumio[26850]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jun 01 09:26:28 volumio volumio[26850]: 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 Jun 01 09:26:28 volumio volumio[26850]: 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 Jun 01 09:26:28 volumio volumio[26850]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:26:28 volumio volumio[26850]: info: CoreStateMachine::pushState Jun 01 09:26:28 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:28 volumio volumio[26850]: info: Asound.conf file unchanged, so no further update is needed Jun 01 09:26:28 volumio volumio[26850]: info: Output device has changed, restarting MPD Jun 01 09:26:28 volumio volumio[26850]: info: Output device has changed, restarting Shairport Sync Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:28 volumio sudo[26968]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:26:28 volumio sudo[26968]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:28 volumio sudo[26968]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:28 volumio volumio[26850]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:28 volumio sudo[26969]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:26:28 volumio volumio[26850]: info: ___________ START PLUGINS ___________ Jun 01 09:26:28 volumio sudo[26969]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:28 volumio volumio[26850]: info: ControllerMpd::onStart: Initializing MPD Jun 01 09:26:28 volumio volumio[26850]: info: Creating MPD Configuration file Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:28 volumio volumio[26850]: info: [1780320388286] CoreMusicLibrary::Adding element Media Servers Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:28 volumio volumio[26850]: info: UPNP Browser: Client initialized successfully Jun 01 09:26:28 volumio sudo[26977]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 01 09:26:28 volumio sudo[26977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:28 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jun 01 09:26:28 volumio sudo[26979]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:26:28 volumio sudo[26979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:28 volumio sudo[26981]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:26:28 volumio sudo[26979]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:28 volumio sudo[26981]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:28 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 01 09:26:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 09:26:28 volumio systemd[1]: mpd.service: Consumed 1.967s CPU time. Jun 01 09:26:28 volumio volumio[26850]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:28 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 01 09:26:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 09:26:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 09:26:28 volumio volumio-remote-updater[761]: [2026-06-01 09:26:28] [connect] Successful connection Jun 01 09:26:28 volumio volumio[26850]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:28 volumio volumio[26850]: info: [1780320388405] CoreMusicLibrary::Adding element Last_100 Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:28 volumio volumio[26850]: info: [1780320388408] CoreMusicLibrary::Adding element Webradio Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:28 volumio volumio[26850]: info: Initializing BBC Radios Jun 01 09:26:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 09:26:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 09:26:28 volumio sudo[26977]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:28 volumio volumio[26850]: info: Creating Spotify config file Jun 01 09:26:28 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:28 volumio sudo[27003]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 09:26:28 volumio sudo[27003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 01 09:26:28 volumio sudo[27003]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:28 volumio volumio[26850]: info: Volumio Calling Home Jun 01 09:26:28 volumio sudo[26887]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:28 volumio volumio[26850]: 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 Jun 01 09:26:29 volumio volumio[26850]: info: MPD Permissions set Jun 01 09:26:29 volumio volumio[26850]: info: MPD Permissions set Jun 01 09:26:29 volumio volumio-remote-updater[761]: [2026-06-01 09:26:29] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1780320388 101 Jun 01 09:26:29 volumio volumio[26850]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jun 01 09:26:29 volumio volumio[26850]: info: Spotify config file written Jun 01 09:26:29 volumio volumio[26850]: info: Discovery: adding 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:26:29 volumio volumio[26850]: info: Discovery: Found device Volumio Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:29 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:29 volumio volumio[26850]: 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: 2 Jun 01 09:26:29 volumio sudo[27014]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 01 09:26:29 volumio sudo[27014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:29 volumio volumio[26928]: Starting albumart workers Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26932]: Starting albumart workers Jun 01 09:26:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:29 volumio volumio[26850]: info: No need to fix Spotify hosts Jun 01 09:26:29 volumio volumio[26850]: info: Discovery: this is already registered, 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:26:29 volumio volumio[26850]: info: Discovery: Found device Volumio Jun 01 09:26:29 volumio volumio[26850]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:29 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:29 volumio go-librespot[27026]: go-librespot daemon starting... Jun 01 09:26:29 volumio sudo[27014]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="app state loaded" Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:29 volumio volumio[26850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 01 09:26:29 volumio volumio[26850]: info: Volumio called home Jun 01 09:26:29 volumio volumio[26934]: Starting albumart workers Jun 01 09:26:29 volumio volumio[26850]: 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: 3 Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=info msg="zeroconf server listening on port 38995" Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:29 volumio volumio[26850]: info: Starting Shairport Sync Jun 01 09:26:29 volumio volumio[26850]: info: Starting Shairport Sync Jun 01 09:26:29 volumio volumio[26850]: info: Starting Shairport Sync Jun 01 09:26:29 volumio sudo[27038]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:29 volumio sudo[27038]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:29 volumio sudo[27039]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:29 volumio sudo[27039]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:29 volumio sudo[27041]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:29 volumio sudo[27041]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:29 volumio volumio[26850]: 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: 3 Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="obtained new client token: AACpeCN7jfWtR3mUxX1hgC9H7Sk0Oj2FaOhWPZHK9TZJeHcVh0T/3jH4rjdcS6gfIHyZZKjNnU8TsWAhfdFkmPdGQPpVLYFl/zagLkr5V0e2A0Wb0hawnJOO+4hmzBUfk0OdafhZhX1Eg1VY2oa5dApbJCpF1wsOyQnq9I+0J3iHx7jxsFA5SVf+Vuf+75RoFT1duXQmu+pA0g5p4QgQwX5YNZYXmbC8Y0ccZk6PiD1bW8UMknuOVbOI7Q==" Jun 01 09:26:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 01 09:26:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 01 09:26:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:29 volumio systemd[1]: shairport-sync.service: Consumed 1.644s CPU time. Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:29 volumio volumio[26850]: info: New Spotify access tokenBQC5uFKiDG... Jun 01 09:26:29 volumio volumio[26850]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 01 09:26:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:29 volumio sudo[27039]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:29 volumio volumio[26850]: 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: 3 Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:29 volumio go-librespot[27027]: time="2026-06-01T09:26:29-04:00" level=debug msg="completed challenge" Jun 01 09:26:30 volumio sudo[27038]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:30 volumio volumio[26850]: info: Shairport-Sync Started Jun 01 09:26:30 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 01 09:26:30 volumio volumio[26850]: Error adding Membership: Error: addMembership EINVAL Jun 01 09:26:30 volumio volumio[26850]: info: Shairport-Sync Started Jun 01 09:26:30 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 01 09:26:30 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:30 volumio go-librespot[27027]: time="2026-06-01T09:26:30-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:30 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio sudo[27041]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:30 volumio volumio[26850]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:30 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:30 volumio volumio[26850]: info: Shairport-Sync Started Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: SPOTIFY: User informations: {"account_id":"W4wCmVA8pZ","country":"US","display_name":"122559042","email":"jarrod@higginscomputer.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/122559042"},"followers":{"href":null,"total":3},"href":"https://api.spotify.com/v1/users/122559042","id":"122559042","images":[],"product":"premium","type":"user","uri":"spotify:user:122559042"} Jun 01 09:26:30 volumio volumio[26850]: info: Spotify Successfully logged in Jun 01 09:26:30 volumio volumio[26850]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:30 volumio volumio[26850]: info: [1780320390390] CoreMusicLibrary::Adding element Spotify Jun 01 09:26:30 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:30 volumio volumio[26850]: Cannot find translation for source Spotify Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio volumio[26850]: 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: 3 Jun 01 09:26:30 volumio go-librespot[27027]: time="2026-06-01T09:26:30-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:30 volumio go-librespot[27027]: time="2026-06-01T09:26:30-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:30 volumio go-librespot[27027]: time="2026-06-01T09:26:30-04:00" level=debug msg="completed challenge" Jun 01 09:26:30 volumio go-librespot[27027]: time="2026-06-01T09:26:30-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:30 volumio mpd[27009]: 2026-06-01T09:26:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 01 09:26:30 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jun 01 09:26:30 volumio sudo[26969]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:30 volumio sudo[26981]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:30 volumio volumio[26850]: info: Completed starting Core Plugins Jun 01 09:26:30 volumio volumio[26850]: info: ------------------------------------------- Jun 01 09:26:30 volumio volumio[26850]: info: ----- MyVolumio plugins startup ---- Jun 01 09:26:30 volumio volumio[26850]: info: ------------------------------------------- Jun 01 09:26:30 volumio volumio[26850]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 01 09:26:30 volumio volumio[26850]: error: MPD error: The expression evaluated to a falsy value: Jun 01 09:26:30 volumio volumio[26850]: assert.ok(self.idling) Jun 01 09:26:30 volumio volumio[26850]: error: The expression evaluated to a falsy value: Jun 01 09:26:30 volumio volumio[26850]: assert.ok(self.idling) Jun 01 09:26:30 volumio volumio[26850]: info: MPD running with PID27009 Jun 01 09:26:30 volumio volumio[26850]: ,establishing connection Jun 01 09:26:30 volumio volumio[26850]: error: updateQueue error: null Jun 01 09:26:30 volumio volumio[26850]: error: updateQueue error: null Jun 01 09:26:31 volumio go-librespot[27027]: time="2026-06-01T09:26:31-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:26:31 volumio go-librespot[27027]: time="2026-06-01T09:26:31-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:31 volumio go-librespot[27027]: time="2026-06-01T09:26:31-04:00" level=debug msg="completed challenge" Jun 01 09:26:31 volumio go-librespot[27027]: time="2026-06-01T09:26:31-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:32 volumio go-librespot[27027]: time="2026-06-01T09:26:32-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:26:32 volumio go-librespot[27027]: time="2026-06-01T09:26:32-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:32 volumio go-librespot[27027]: time="2026-06-01T09:26:32-04:00" level=debug msg="completed challenge" Jun 01 09:26:32 volumio go-librespot[27027]: time="2026-06-01T09:26:32-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:32 volumio volumio[26850]: info: go-librespot daemon successfully initialized Jun 01 09:26:33 volumio go-librespot[27027]: time="2026-06-01T09:26:33-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jun 01 09:26:33 volumio go-librespot[27027]: time="2026-06-01T09:26:33-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:33 volumio go-librespot[27027]: time="2026-06-01T09:26:33-04:00" level=debug msg="completed challenge" Jun 01 09:26:33 volumio go-librespot[27027]: time="2026-06-01T09:26:33-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:33 volumio go-librespot[27027]: time="2026-06-01T09:26:33-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:26:34 volumio go-librespot[27027]: time="2026-06-01T09:26:34-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:34 volumio go-librespot[27027]: time="2026-06-01T09:26:34-04:00" level=debug msg="completed challenge" Jun 01 09:26:34 volumio go-librespot[27027]: time="2026-06-01T09:26:34-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:34 volumio go-librespot[27027]: time="2026-06-01T09:26:34-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:26:35 volumio volumio[26850]: info: Initializing connection to go-librespot Websocket Jun 01 09:26:35 volumio volumio[26850]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 09:26:35 volumio volumio[26850]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 01 09:26:36 volumio sudo[27099]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:26:36 volumio sudo[27099]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:36 volumio sudo[27101]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:26:36 volumio sudo[27101]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:36 volumio sudo[27099]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:36 volumio sudo[27101]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:36 volumio sudo[27103]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 01 09:26:36 volumio sudo[27103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:36 volumio sudo[27103]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:36 volumio volumio[26850]: info: Upmpdcli Daemon Started Jun 01 09:26:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jun 01 09:26:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:37 volumio go-librespot[27107]: go-librespot daemon starting... Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=debug msg="app state loaded" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=info msg="zeroconf server listening on port 33957" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=debug msg="obtained new client token: AAB8txwIf2aTNfxDl8+0L8XJQvYBY81VfPU1513OFqxaLR/Sg3jbt6rinubs899UL6DLtAzjwDHl9LHPqvwXYbcy7pdZCcc0w/tvz70kGcvhejWJxufFhbeeCXj6RVKgpEXaL5hA8UaSpISNXkWMldZumVppxu/GIpOMG7ahH1flV30q7+SPg9MCQaSWvJBjysX6XJGsM34by2w2WXXdOGvgJYy2ewMu0m0gtsCWGRIwU6IJRwHuzX9DGA==" Jun 01 09:26:37 volumio go-librespot[27108]: time="2026-06-01T09:26:37-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=debug msg="completed challenge" Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:38 volumio volumio[26850]: info: Initializing connection to go-librespot Websocket Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=debug msg="new websocket client" Jun 01 09:26:38 volumio volumio[26850]: info: Connection to go-librespot Websocket established Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=debug msg="completed challenge" Jun 01 09:26:38 volumio go-librespot[27108]: time="2026-06-01T09:26:38-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 01 09:26:39 volumio volumio[26850]: info: Adding plugin bluetooth to MyMusic Plugins Jun 01 09:26:39 volumio volumio[26850]: info: Adding plugin multiroom to MyMusic Plugins Jun 01 09:26:39 volumio volumio[26850]: info: Adding plugin metavolumio to MyMusic Plugins Jun 01 09:26:39 volumio volumio[26850]: info: Adding plugin cd_controller to MyMusic Plugins Jun 01 09:26:39 volumio volumio[26850]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 01 09:26:39 volumio volumio[26850]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 01 09:26:39 volumio volumio[26850]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 01 09:26:39 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:39.222-04:00 level=ERROR msg="failed to update discovery on Wi-Fi info change" error="failed to get system info: could not get system info: context deadline exceeded" Jun 01 09:26:39 volumio go-librespot[27108]: time="2026-06-01T09:26:39-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:26:39 volumio go-librespot[27108]: time="2026-06-01T09:26:39-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:39 volumio go-librespot[27108]: time="2026-06-01T09:26:39-04:00" level=debug msg="completed challenge" Jun 01 09:26:39 volumio go-librespot[27108]: time="2026-06-01T09:26:39-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 01 09:26:39 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:39 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:39 volumio volumio[26850]: info: Starting MyVolumio Remote Streaming Endpoints Jun 01 09:26:39 volumio volumio[26850]: info: MyVolumio login type: Token Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 01 09:26:39 volumio volumio[26850]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=debug msg="completed challenge" Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:40 volumio volumio[26850]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 01 09:26:40 volumio volumio[26850]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 01 09:26:40 volumio volumio[26850]: info: Streaming services startup Jun 01 09:26:40 volumio volumio[26850]: info: Starting Streaming Daemon Jun 01 09:26:40 volumio sudo[27118]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:26:40 volumio sudo[27118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:40 volumio volumio[26850]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 01 09:26:40 volumio sudo[27118]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:40 volumio volumio[26850]: error: Cannot start Volumio Streaming Daemon Jun 01 09:26:40 volumio volumio[26850]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:26:40 volumio volumio[26850]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:26:40 volumio volumio[26850]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=debug msg="completed challenge" Jun 01 09:26:40 volumio go-librespot[27108]: time="2026-06-01T09:26:40-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:40 volumio volumio[26850]: info: MyVolumio token set successfully Jun 01 09:26:40 volumio volumio[26850]: info: MYVOLUMIO: Adding device Jun 01 09:26:40 volumio volumio[26850]: info: MYVOLUMIO: Evaluating Server Jun 01 09:26:41 volumio volumio[26850]: info: MyVolumio status changed Jun 01 09:26:41 volumio volumio[26850]: info: Streaming services startup Jun 01 09:26:41 volumio volumio[26850]: info: Starting Streaming Daemon Jun 01 09:26:41 volumio volumio[26850]: info: Removing browser output: myVolumio user plan is not superstar Jun 01 09:26:41 volumio volumio[26850]: info: Removing audio output: Jun 01 09:26:41 volumio volumio[26850]: info: Stoppping Tunnel 1 Jun 01 09:26:41 volumio sudo[27146]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:26:41 volumio sudo[27146]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:41 volumio sudo[27148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jun 01 09:26:41 volumio sudo[27148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio sudo[27146]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio volumio[26850]: error: Cannot start Volumio Streaming Daemon Jun 01 09:26:41 volumio volumio[26850]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:26:41 volumio volumio[26850]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:26:41 volumio sudo[27148]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:41 volumio volumio[26850]: info: Remote SSH Stopped Jun 01 09:26:41 volumio volumio[26850]: info: Setting Geolocation for MyVolumio to us4 Jun 01 09:26:41 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:41 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:41 volumio volumio[26850]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:41 volumio volumio[26850]: info: Getting Spotify volume Jun 01 09:26:41 volumio volumio[26850]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jun 01 09:26:41 volumio go-librespot[27108]: time="2026-06-01T09:26:41-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:26:41 volumio volumio[26850]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:41 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:41 volumio volumio[26850]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Jun 01 09:26:41 volumio volumio[26850]: SPOTIFY: SPOTIFY VOLUME undefined Jun 01 09:26:41 volumio volumio[26850]: SPOTIFY: VOLUMIO VOLUME 33 Jun 01 09:26:41 volumio volumio[26850]: info: Aligning Spotify Volume to Volumio Volume Jun 01 09:26:41 volumio volumio[26850]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:41 volumio volumio[26850]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:41 volumio volumio[26850]: info: Setting Spotify Volume from Volumio: 33 Jun 01 09:26:41 volumio go-librespot[27108]: time="2026-06-01T09:26:41-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:41 volumio go-librespot[27108]: time="2026-06-01T09:26:41-04:00" level=debug msg="completed challenge" Jun 01 09:26:41 volumio volumio[26850]: info: Successfully Added MyVolumio device Jun 01 09:26:41 volumio go-librespot[27108]: time="2026-06-01T09:26:41-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:41 volumio go-librespot[27108]: time="2026-06-01T09:26:41-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:26:41 volumio volumio[26850]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:26:41 volumio volumio[26850]: Error: socket hang up Jun 01 09:26:41 volumio volumio[26850]: at connResetException (node:internal/errors:720:14) Jun 01 09:26:41 volumio volumio[26850]: at Socket.socketOnEnd (node:_http_client:519:23) Jun 01 09:26:41 volumio volumio[26850]: at Socket.emit (node:events:526:35) Jun 01 09:26:41 volumio volumio[26850]: at endReadableNT (node:internal/streams/readable:1376:12) Jun 01 09:26:41 volumio volumio[26850]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jun 01 09:26:41 volumio volumio[26850]: code: 'ECONNRESET', Jun 01 09:26:41 volumio volumio[26850]: response: undefined Jun 01 09:26:41 volumio volumio[26850]: } Jun 01 09:26:41 volumio volumio[26850]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:26:42 volumio sudo[27165]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-01 09:25' Jun 01 09:26:42 volumio sudo[27165]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:42 volumio sudo[27165]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:43 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:43.356-04:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Jun 01 09:26:43 volumio volumio-remote-updater[761]: [2026-06-01 09:26:43] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 01 09:26:43 volumio volumio-remote-updater[761]: [2026-06-01 09:26:43] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 01 09:26:43 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:43 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:43.359-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:26:43 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jun 01 09:26:43 volumio systemd[1]: volumio.service: Consumed 15.772s CPU time. Jun 01 09:26:43 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:26:43 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:26:43 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 34097. Jun 01 09:26:43 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:26:43 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jun 01 09:26:43 volumio systemd[1]: volumio.service: Consumed 15.772s CPU time. Jun 01 09:26:43 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jun 01 09:26:43 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:26:44 volumio volumio5-onboarding[21559]: time=2026-06-01T09:26:44.361-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:26:44 volumio volumio[27180]: info: ------------------------------------------- Jun 01 09:26:44 volumio volumio[27180]: info: ----- Volumio3 ---- Jun 01 09:26:44 volumio volumio[27180]: info: ------------------------------------------- Jun 01 09:26:44 volumio volumio[27180]: info: ----- System startup ---- Jun 01 09:26:44 volumio volumio[27180]: info: ------------------------------------------- Jun 01 09:26:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Jun 01 09:26:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:44 volumio go-librespot[27201]: go-librespot daemon starting... Jun 01 09:26:44 volumio go-librespot[27202]: time="2026-06-01T09:26:44-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:44 volumio go-librespot[27202]: time="2026-06-01T09:26:44-04:00" level=debug msg="app state loaded" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:45 volumio volumio[27180]: info: MYVOLUMIO Environment detected Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=info msg="zeroconf server listening on port 40989" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:45 volumio volumio[27180]: info: Plugin folders cleanup Jun 01 09:26:45 volumio volumio[27180]: info: Scanning into folder /volumio/app/plugins/ Jun 01 09:26:45 volumio volumio[27180]: info: Scanning category audio_interface Jun 01 09:26:45 volumio volumio[27180]: info: Scanning category miscellanea Jun 01 09:26:45 volumio volumio[27180]: info: Scanning category music_service Jun 01 09:26:45 volumio volumio[27180]: info: Scanning category plugins.json Jun 01 09:26:45 volumio volumio[27180]: info: Scanning category system_controller Jun 01 09:26:45 volumio volumio[27180]: info: Scanning category user_interface Jun 01 09:26:45 volumio volumio[27180]: info: Scanning into folder /data/plugins/ Jun 01 09:26:45 volumio volumio[27180]: info: Scanning category music_service Jun 01 09:26:45 volumio volumio[27180]: info: Plugin folders cleanup completed Jun 01 09:26:45 volumio volumio[27180]: info: ------------------------------------------- Jun 01 09:26:45 volumio volumio[27180]: info: ----- Core plugins startup ---- Jun 01 09:26:45 volumio volumio[27180]: info: ------------------------------------------- Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugins from folder /volumio/app/plugins/ Jun 01 09:26:45 volumio volumio[27180]: info: Adding plugin upnp to MyMusic Plugins Jun 01 09:26:45 volumio volumio[27180]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 01 09:26:45 volumio volumio[27180]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugins from folder /data/plugins/ Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "system"... Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "appearance"... Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=debug msg="obtained new client token: AADsL9bdxdxzNcWcY6UDt8PBmiR4QW+v9+i1Dw8ndbKweniwIZogKzBfrvTZNPWt545DLVCmzGni1xL44sg5mpXL8HvJpFYVsG0aLwdYu+Hdj/bqIaFfTf1vt/pB3cCeeLaTn7r7xJJQAcAr6EUSNnK7HvB9QbbMDUk2446GhidKaT2uJfYIx0nfESOiU09p7zYDt6hJFR+O5Tfcgb2arTs8kWeA+Iz6AUkQCcKFZuZ1gCpyMwv1IF6dGQ==" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=debug msg="completed challenge" Jun 01 09:26:45 volumio go-librespot[27202]: time="2026-06-01T09:26:45-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "network"... Jun 01 09:26:45 volumio volumio[27180]: info: Refreshing Cached IP Addresses Jun 01 09:26:45 volumio sudo[27218]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:26:45 volumio sudo[27218]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:45 volumio sudo[27220]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:26:45 volumio sudo[27220]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:45 volumio sudo[27218]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "services"... Jun 01 09:26:45 volumio sudo[27220]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "volumio5onboarding"... Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "alsa_controller"... Jun 01 09:26:45 volumio sudo[27231]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 01 09:26:45 volumio sudo[27231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:45 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "wizard"... Jun 01 09:26:45 volumio volumio[27180]: info: Loading plugin "networkfs"... Jun 01 09:26:45 volumio volumio[27180]: info: Starting Udev Watcher for removable devices Jun 01 09:26:46 volumio volumio[27180]: info: Ignoring mount for partition: boot Jun 01 09:26:46 volumio volumio[27180]: info: Ignoring mount for partition: volumio Jun 01 09:26:46 volumio volumio[27180]: info: Ignoring mount for partition: volumio_data Jun 01 09:26:46 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:46 volumio volumio[27180]: info: Loading plugin "volumio_command_line_client"... Jun 01 09:26:46 volumio volumio[27180]: info: Loading plugin "upnp"... Jun 01 09:26:46 volumio volumio[27180]: info: [1780320406030] Starting Upmpd Daemon Jun 01 09:26:46 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:46 volumio volumio[27180]: info: Loading plugin "my_music"... Jun 01 09:26:46 volumio volumio[27180]: info: Loading plugin "mpd"... Jun 01 09:26:46 volumio go-librespot[27202]: time="2026-06-01T09:26:46-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:46 volumio volumio[27180]: info: Loading plugin "upnp_browser"... Jun 01 09:26:46 volumio volumio[27180]: info: Starting UPNP Browser Jun 01 09:26:46 volumio volumio[27180]: info: Loading plugin "alarm-clock"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "airplay_emulation"... Jun 01 09:26:47 volumio volumio[27180]: info: Starting Shairport Sync Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "last_100"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "webradio"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "i2s_dacs"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "volumiodiscovery"... Jun 01 09:26:47 volumio volumio[27180]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:47 volumio volumio[27180]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:47 volumio volumio[27180]: *** WARNING *** For more information see Jun 01 09:26:47 volumio volumio[27180]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:47 volumio volumio[27180]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:47 volumio volumio[27180]: *** WARNING *** For more information see Jun 01 09:26:47 volumio node[27180]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:47 volumio node[27180]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:47 volumio node[27180]: *** WARNING *** For more information see Jun 01 09:26:47 volumio node[27180]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:26:47 volumio node[27180]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:26:47 volumio node[27180]: *** WARNING *** For more information see Jun 01 09:26:47 volumio volumio[27180]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 01 09:26:47 volumio volumio[27180]: info: Discovery: Started advertising with name: Volumio Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "spop"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "outputs"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "albumart"... Jun 01 09:26:47 volumio volumio[27180]: info: Plugin example_plugin is not enabled Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "inputs"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "updater_comm"... Jun 01 09:26:47 volumio volumio[27180]: info: Plugin mpdemulation is not enabled Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "rest_api"... Jun 01 09:26:47 volumio volumio[27180]: info: Loading plugin "websocket"... Jun 01 09:26:47 volumio volumio[27180]: info: Starting Socket.io Server version 1.7.4 Jun 01 09:26:47 volumio volumio[27180]: info: Loading i18n strings for locale en Jun 01 09:26:47 volumio volumio[27180]: Updating browse sources language Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::initPlayerControls Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:47 volumio volumio[27180]: Express server listening on port 3000 Jun 01 09:26:47 volumio volumio[27180]: [Metrics] WebUI: 3s 412.41ms Jun 01 09:26:47 volumio volumio[27180]: info: CoreStateMachine::resetVolumioState Jun 01 09:26:47 volumio volumio[27180]: info: CoreStateMachine::getcurrentVolume Jun 01 09:26:47 volumio volumio[27180]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:26:47 volumio volumio[27180]: info: Volumio Network Manager: Network status updated: 1 Jun 01 09:26:48 volumio volumio[27253]: Forking 3 albumart workers Jun 01 09:26:48 volumio volumio[27180]: 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 Jun 01 09:26:48 volumio volumio[27180]: 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 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:48 volumio volumio[27180]: info: Reloading queue from file Jun 01 09:26:48 volumio volumio[27180]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:26:48 volumio volumio[27180]: info: CoreStateMachine::pushState Jun 01 09:26:48 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:48 volumio volumio[27180]: info: CoreStateMachine::updateTrackBlock Jun 01 09:26:48 volumio volumio[27180]: info: CorePlayQueue::getTrackBlock Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:26:48 volumio volumio[27180]: info: CoreStateMachine::setRepeat null single undefined Jun 01 09:26:48 volumio volumio[27180]: info: CoreStateMachine::pushState Jun 01 09:26:48 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:48 volumio volumio[27180]: info: CoreStateMachine::setRandom null Jun 01 09:26:48 volumio volumio[27180]: info: CoreStateMachine::pushState Jun 01 09:26:48 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:48 volumio volumio[27180]: info: Setting Device type: Raspberry PI Jun 01 09:26:48 volumio volumio[27180]: info: Completed loading Core Plugins Jun 01 09:26:48 volumio volumio[27180]: info: Preparing to generate the ALSA configuration file Jun 01 09:26:48 volumio volumio[27180]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jun 01 09:26:48 volumio volumio[27180]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Jun 01 09:26:48 volumio volumio[27180]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jun 01 09:26:48 volumio volumio[27180]: 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 Jun 01 09:26:48 volumio volumio[27180]: 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 Jun 01 09:26:48 volumio volumio[27180]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:26:48 volumio volumio[27180]: info: CoreStateMachine::pushState Jun 01 09:26:48 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioPushState Jun 01 09:26:48 volumio volumio[27180]: info: Asound.conf file unchanged, so no further update is needed Jun 01 09:26:48 volumio volumio[27180]: info: Output device has changed, restarting MPD Jun 01 09:26:48 volumio volumio[27180]: info: Output device has changed, restarting Shairport Sync Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:48 volumio sudo[27307]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:26:48 volumio sudo[27307]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:48 volumio volumio[27180]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:48 volumio volumio[27180]: info: ___________ START PLUGINS ___________ Jun 01 09:26:48 volumio sudo[27307]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:48 volumio sudo[27309]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:26:48 volumio sudo[27309]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:48 volumio volumio[27180]: info: ControllerMpd::onStart: Initializing MPD Jun 01 09:26:48 volumio volumio[27180]: info: Creating MPD Configuration file Jun 01 09:26:48 volumio volumio-remote-updater[761]: [2026-06-01 09:26:48] [connect] Successful connection Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:48 volumio volumio[27180]: info: [1780320408371] CoreMusicLibrary::Adding element Media Servers Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:48 volumio volumio[27180]: info: UPNP Browser: Client initialized successfully Jun 01 09:26:48 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jun 01 09:26:48 volumio sudo[27317]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 01 09:26:48 volumio sudo[27317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:48 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 01 09:26:48 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 09:26:48 volumio systemd[1]: mpd.service: Consumed 1.993s CPU time. Jun 01 09:26:48 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 01 09:26:48 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 09:26:48 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 09:26:48 volumio sudo[27320]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:26:48 volumio sudo[27320]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:48 volumio sudo[27321]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:26:48 volumio sudo[27321]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:48 volumio sudo[27320]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:48 volumio volumio[27180]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:48 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 09:26:48 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 09:26:48 volumio volumio[27180]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:48 volumio volumio[27180]: info: [1780320408517] CoreMusicLibrary::Adding element Last_100 Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:48 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 01 09:26:48 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 09:26:48 volumio sudo[27317]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:48 volumio volumio[27180]: info: [1780320408526] CoreMusicLibrary::Adding element Webradio Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:48 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 01 09:26:48 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 09:26:48 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:48 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 09:26:48 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 09:26:48 volumio volumio[27180]: info: Initializing BBC Radios Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:48 volumio sudo[27336]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 09:26:48 volumio sudo[27336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 01 09:26:48 volumio volumio[27180]: info: Creating Spotify config file Jun 01 09:26:48 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:48 volumio sudo[27336]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:48 volumio sudo[27231]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:48 volumio volumio[27180]: info: Volumio Calling Home Jun 01 09:26:48 volumio volumio[27269]: Starting albumart workers Jun 01 09:26:49 volumio volumio[27270]: Starting albumart workers Jun 01 09:26:49 volumio volumio[27267]: Starting albumart workers Jun 01 09:26:49 volumio volumio[27180]: 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 Jun 01 09:26:49 volumio volumio[27180]: info: Discovery: adding 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:26:49 volumio volumio[27180]: info: Discovery: Found device Volumio Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:49 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:49 volumio volumio[27180]: info: Discovery: this is already registered, 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:26:49 volumio volumio[27180]: info: Discovery: Found device Volumio Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:49 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:49 volumio volumio[27180]: info: MPD Permissions set Jun 01 09:26:49 volumio volumio[27180]: info: MPD Permissions set Jun 01 09:26:49 volumio volumio-remote-updater[761]: [2026-06-01 09:26:49] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1780320408 101 Jun 01 09:26:49 volumio volumio[27180]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jun 01 09:26:49 volumio volumio[27180]: info: Spotify config file written Jun 01 09:26:49 volumio sudo[27357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 01 09:26:49 volumio sudo[27357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:49 volumio volumio[27180]: 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: 2 Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jun 01 09:26:49 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jun 01 09:26:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:49 volumio go-librespot[27367]: go-librespot daemon starting... Jun 01 09:26:49 volumio sudo[27357]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio go-librespot[27371]: time="2026-06-01T09:26:49-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:49 volumio go-librespot[27371]: time="2026-06-01T09:26:49-04:00" level=debug msg="app state loaded" Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:26:49 volumio volumio[27180]: info: No need to fix Spotify hosts Jun 01 09:26:49 volumio go-librespot[27371]: time="2026-06-01T09:26:49-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:49 volumio volumio[27180]: 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: 2 Jun 01 09:26:49 volumio volumio[27180]: info: Received Get System Info Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 09:26:49 volumio volumio[27180]: info: Discovery: Getting this device information Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:49 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:49 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 09:26:49 volumio volumio[27180]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jun 01 09:26:49 volumio volumio[27180]: info: Volumio called home Jun 01 09:26:50 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 01 09:26:50 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=info msg="zeroconf server listening on port 43713" Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:50 volumio volumio[27180]: info: Starting Shairport Sync Jun 01 09:26:50 volumio volumio[27180]: info: Starting Shairport Sync Jun 01 09:26:50 volumio volumio[27180]: info: Starting Shairport Sync Jun 01 09:26:50 volumio sudo[27398]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:50 volumio sudo[27398]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:50 volumio sudo[27400]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:50 volumio sudo[27400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:50 volumio sudo[27402]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:26:50 volumio sudo[27402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:50 volumio volumio[27180]: info: CoreCommandRouter::volumioGetState Jun 01 09:26:50 volumio volumio[27180]: info: CorePlayQueue::getTrack 0 Jun 01 09:26:50 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 01 09:26:50 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 01 09:26:50 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:50 volumio systemd[1]: shairport-sync.service: Consumed 1.580s CPU time. Jun 01 09:26:50 volumio volumio[27180]: info: New Spotify access tokenBQBc3vHBhV... Jun 01 09:26:50 volumio volumio[27180]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=debug msg="obtained new client token: AABAS9XTm+8AqM+8TWZq9d8JnmxqW+Nb5FQx01oJEZtp77RrZakOCI1n5Snpd49zhovu+yKxLPSpXNjHWLX+zkhXKo5SpDkFnl/wQJvsWII8vN33poQQekSGxRxfJJ5asC3kJiwvpVnIlgWKun0jiw5srz6qX0QOKIKyyDNyWJdGWbC5ktt7BMNVIpmv2JMSljJ41BQbvMK6K4QPtAFVsXOddOXYIWPeYVsOLXwQ1BVpBAzQmCFjls8=" Jun 01 09:26:50 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:26:50 volumio sudo[27398]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:50 volumio sudo[27400]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:50 volumio sudo[27402]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:50 volumio volumio[27180]: info: Shairport-Sync Started Jun 01 09:26:50 volumio volumio[27180]: Error adding Membership: Error: addMembership EINVAL Jun 01 09:26:50 volumio volumio[27180]: info: Shairport-Sync Started Jun 01 09:26:50 volumio volumio[27180]: info: Shairport-Sync Started Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=debug msg="completed challenge" Jun 01 09:26:50 volumio go-librespot[27371]: time="2026-06-01T09:26:50-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:50 volumio volumio[27180]: SPOTIFY: User informations: {"account_id":"W4wCmVA8pZ","country":"US","display_name":"122559042","email":"jarrod@higginscomputer.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/122559042"},"followers":{"href":null,"total":3},"href":"https://api.spotify.com/v1/users/122559042","id":"122559042","images":[],"product":"premium","type":"user","uri":"spotify:user:122559042"} Jun 01 09:26:50 volumio volumio[27180]: info: Spotify Successfully logged in Jun 01 09:26:50 volumio volumio[27180]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:26:50 volumio volumio[27180]: info: [1780320410543] CoreMusicLibrary::Adding element Spotify Jun 01 09:26:50 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:26:50 volumio volumio[27180]: Cannot find translation for source Spotify Jun 01 09:26:50 volumio mpd[27351]: 2026-06-01T09:26:50 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 01 09:26:50 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jun 01 09:26:50 volumio sudo[27321]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:50 volumio sudo[27309]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:50 volumio volumio[27180]: info: Completed starting Core Plugins Jun 01 09:26:50 volumio volumio[27180]: info: ------------------------------------------- Jun 01 09:26:50 volumio volumio[27180]: info: ----- MyVolumio plugins startup ---- Jun 01 09:26:50 volumio volumio[27180]: info: ------------------------------------------- Jun 01 09:26:50 volumio volumio[27180]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 01 09:26:50 volumio volumio[27180]: error: MPD error: The expression evaluated to a falsy value: Jun 01 09:26:50 volumio volumio[27180]: assert.ok(self.idling) Jun 01 09:26:50 volumio volumio[27180]: error: The expression evaluated to a falsy value: Jun 01 09:26:50 volumio volumio[27180]: assert.ok(self.idling) Jun 01 09:26:50 volumio volumio[27180]: error: updateQueue error: null Jun 01 09:26:50 volumio volumio[27180]: info: MPD running with PID27351 Jun 01 09:26:50 volumio volumio[27180]: ,establishing connection Jun 01 09:26:50 volumio volumio[27180]: error: updateQueue error: null Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=debug msg="completed challenge" Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=debug msg="completed challenge" Jun 01 09:26:51 volumio go-librespot[27371]: time="2026-06-01T09:26:51-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:52 volumio go-librespot[27371]: time="2026-06-01T09:26:52-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:26:52 volumio go-librespot[27371]: time="2026-06-01T09:26:52-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:52 volumio go-librespot[27371]: time="2026-06-01T09:26:52-04:00" level=debug msg="completed challenge" Jun 01 09:26:53 volumio go-librespot[27371]: time="2026-06-01T09:26:53-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:53 volumio volumio[27180]: info: go-librespot daemon successfully initialized Jun 01 09:26:53 volumio go-librespot[27371]: time="2026-06-01T09:26:53-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jun 01 09:26:53 volumio go-librespot[27371]: time="2026-06-01T09:26:53-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:53 volumio go-librespot[27371]: time="2026-06-01T09:26:53-04:00" level=debug msg="completed challenge" Jun 01 09:26:53 volumio go-librespot[27371]: time="2026-06-01T09:26:53-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:54 volumio go-librespot[27371]: time="2026-06-01T09:26:54-04:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jun 01 09:26:54 volumio go-librespot[27371]: time="2026-06-01T09:26:54-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:54 volumio go-librespot[27371]: time="2026-06-01T09:26:54-04:00" level=debug msg="completed challenge" Jun 01 09:26:54 volumio go-librespot[27371]: time="2026-06-01T09:26:54-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:54 volumio go-librespot[27371]: time="2026-06-01T09:26:54-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:26:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:26:55 volumio volumio[27180]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 01 09:26:56 volumio sudo[27441]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:26:56 volumio sudo[27441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:56 volumio sudo[27441]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:56 volumio sudo[27443]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:26:56 volumio sudo[27443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:56 volumio sudo[27443]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:56 volumio sudo[27446]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 01 09:26:56 volumio sudo[27446]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:26:56 volumio volumio[27180]: info: Initializing connection to go-librespot Websocket Jun 01 09:26:56 volumio volumio[27180]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 09:26:56 volumio sudo[27446]: pam_unix(sudo:session): session closed for user root Jun 01 09:26:56 volumio volumio[27180]: info: Upmpdcli Daemon Started Jun 01 09:26:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jun 01 09:26:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:26:57 volumio go-librespot[27449]: go-librespot daemon starting... Jun 01 09:26:57 volumio go-librespot[27450]: time="2026-06-01T09:26:57-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:26:57 volumio go-librespot[27450]: time="2026-06-01T09:26:57-04:00" level=debug msg="app state loaded" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=info msg="zeroconf server listening on port 36059" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=debug msg="obtained new client token: AABlo5vGAP2nJftj9HMlWhYCCwQSqiRA3qtMJBXgMc9FXUz5fj0HMJvQAhK1dmRsDgsB+eiOQhvxglGTa5ZHx8GUNLNOQqg6dD15Zl/1QFbR/0aq5QU0N6K7p3feaWglI1emH8Q91JUP6PNmtPQxZOHR8SKBuLQ+5p9P/0QrMwpVDsUuS6ixaFoSCGQR9hat0P2c512p7mHM6uUNk8smXP7AQUgYVh61gCgt1JhH3z2k+MabhHAB3EYo8A==" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=debug msg="completed challenge" Jun 01 09:26:58 volumio go-librespot[27450]: time="2026-06-01T09:26:58-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 01 09:26:59 volumio volumio[27180]: info: Adding plugin bluetooth to MyMusic Plugins Jun 01 09:26:59 volumio volumio[27180]: info: Adding plugin multiroom to MyMusic Plugins Jun 01 09:26:59 volumio volumio[27180]: info: Adding plugin metavolumio to MyMusic Plugins Jun 01 09:26:59 volumio volumio[27180]: info: Adding plugin cd_controller to MyMusic Plugins Jun 01 09:26:59 volumio volumio[27180]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 01 09:26:59 volumio volumio[27180]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 01 09:26:59 volumio volumio[27180]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 01 09:26:59 volumio go-librespot[27450]: time="2026-06-01T09:26:59-04:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:443, retrying with a different AP" error="dial tcp 104.154.127.247:443: connect: connection refused" Jun 01 09:26:59 volumio go-librespot[27450]: time="2026-06-01T09:26:59-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:26:59 volumio go-librespot[27450]: time="2026-06-01T09:26:59-04:00" level=debug msg="completed keyexchange" Jun 01 09:26:59 volumio go-librespot[27450]: time="2026-06-01T09:26:59-04:00" level=debug msg="completed challenge" Jun 01 09:26:59 volumio go-librespot[27450]: time="2026-06-01T09:26:59-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 01 09:26:59 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:59 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:26:59 volumio volumio[27180]: info: Starting MyVolumio Remote Streaming Endpoints Jun 01 09:26:59 volumio volumio[27180]: info: MyVolumio login type: Token Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 01 09:26:59 volumio volumio[27180]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 01 09:27:00 volumio go-librespot[27450]: time="2026-06-01T09:27:00-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:27:00 volumio volumio[27180]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 01 09:27:00 volumio volumio[27180]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 01 09:27:00 volumio volumio[27180]: info: Streaming services startup Jun 01 09:27:00 volumio volumio[27180]: info: Starting Streaming Daemon Jun 01 09:27:00 volumio sudo[27460]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:27:00 volumio sudo[27460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:00 volumio volumio[27180]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 01 09:27:00 volumio sudo[27460]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:00 volumio volumio[27180]: info: Initializing connection to go-librespot Websocket Jun 01 09:27:00 volumio volumio[27180]: error: Cannot start Volumio Streaming Daemon Jun 01 09:27:00 volumio volumio[27180]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:27:00 volumio volumio[27180]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:27:00 volumio go-librespot[27450]: time="2026-06-01T09:27:00-04:00" level=debug msg="new websocket client" Jun 01 09:27:00 volumio volumio[27180]: info: Connection to go-librespot Websocket established Jun 01 09:27:00 volumio go-librespot[27450]: time="2026-06-01T09:27:00-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:00 volumio go-librespot[27450]: time="2026-06-01T09:27:00-04:00" level=debug msg="completed challenge" Jun 01 09:27:00 volumio go-librespot[27450]: time="2026-06-01T09:27:00-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:00 volumio volumio[27180]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 01 09:27:00 volumio volumio[27180]: info: MyVolumio token set successfully Jun 01 09:27:00 volumio volumio[27180]: info: MYVOLUMIO: Adding device Jun 01 09:27:00 volumio volumio[27180]: info: MYVOLUMIO: Evaluating Server Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jun 01 09:27:01 volumio volumio[27180]: info: MyVolumio status changed Jun 01 09:27:01 volumio volumio[27180]: info: Streaming services startup Jun 01 09:27:01 volumio volumio[27180]: info: Starting Streaming Daemon Jun 01 09:27:01 volumio volumio[27180]: info: Removing browser output: myVolumio user plan is not superstar Jun 01 09:27:01 volumio volumio[27180]: info: Removing audio output: Jun 01 09:27:01 volumio volumio[27180]: info: Stoppping Tunnel 1 Jun 01 09:27:01 volumio sudo[27488]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:27:01 volumio sudo[27488]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:01 volumio sudo[27490]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jun 01 09:27:01 volumio sudo[27490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=debug msg="completed challenge" Jun 01 09:27:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:01 volumio sudo[27488]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:01 volumio volumio[27180]: error: Cannot start Volumio Streaming Daemon Jun 01 09:27:01 volumio volumio[27180]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:27:01 volumio volumio[27180]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:27:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:01 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:01 volumio sudo[27490]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:01 volumio volumio[27180]: info: Remote SSH Stopped Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:01 volumio volumio[27180]: info: Setting Geolocation for MyVolumio to us1 Jun 01 09:27:01 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:01 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:01 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:01 volumio volumio[27180]: info: Successfully Added MyVolumio device Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.65.9:80: connect: connection refused" Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=debug msg="completed challenge" Jun 01 09:27:01 volumio go-librespot[27450]: time="2026-06-01T09:27:01-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:02 volumio volumio[27180]: info: Updating MyVolumio device info Jun 01 09:27:02 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:02 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:02 volumio volumio[27180]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:02 volumio go-librespot[27450]: time="2026-06-01T09:27:02-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:27:02 volumio go-librespot[27450]: time="2026-06-01T09:27:02-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:02 volumio go-librespot[27450]: time="2026-06-01T09:27:02-04:00" level=debug msg="completed challenge" Jun 01 09:27:02 volumio go-librespot[27450]: time="2026-06-01T09:27:02-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:02 volumio go-librespot[27450]: time="2026-06-01T09:27:02-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:27:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:27:02 volumio volumio[27180]: info: Connection to go-librespot Websocket closed Jun 01 09:27:02 volumio volumio[27180]: info: Successfully Updated MyVolumio device Jun 01 09:27:03 volumio volumio[27180]: info: Getting Spotify volume Jun 01 09:27:03 volumio volumio[27180]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:27:03 volumio volumio[27180]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 09:27:03 volumio volumio[27180]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jun 01 09:27:03 volumio volumio[27180]: errno: -111, Jun 01 09:27:03 volumio volumio[27180]: code: 'ECONNREFUSED', Jun 01 09:27:03 volumio volumio[27180]: syscall: 'connect', Jun 01 09:27:03 volumio volumio[27180]: address: '127.0.0.1', Jun 01 09:27:03 volumio volumio[27180]: port: 9879, Jun 01 09:27:03 volumio volumio[27180]: response: undefined Jun 01 09:27:03 volumio volumio[27180]: } Jun 01 09:27:03 volumio volumio[27180]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:27:03 volumio sudo[27507]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-01 09:26' Jun 01 09:27:03 volumio sudo[27507]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:03 volumio sudo[27507]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:05 volumio volumio-remote-updater[761]: [2026-06-01 09:27:05] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jun 01 09:27:05 volumio volumio-remote-updater[761]: [2026-06-01 09:27:05] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jun 01 09:27:05 volumio volumio5-onboarding[21559]: time=2026-06-01T09:27:05.824-04:00 level=ERROR msg="failed reading message" component=volumio/socket error="websocket: close 1006 (abnormal closure): unexpected EOF" Jun 01 09:27:05 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:27:05 volumio volumio5-onboarding[21559]: time=2026-06-01T09:27:05.826-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:27:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jun 01 09:27:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:27:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:27:05 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jun 01 09:27:05 volumio systemd[1]: volumio.service: Consumed 15.503s CPU time. Jun 01 09:27:05 volumio go-librespot[27515]: go-librespot daemon starting... Jun 01 09:27:05 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:27:05 volumio go-librespot[27518]: time="2026-06-01T09:27:05-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:27:05 volumio go-librespot[27518]: time="2026-06-01T09:27:05-04:00" level=debug msg="app state loaded" Jun 01 09:27:05 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:27:05 volumio go-librespot[27518]: time="2026-06-01T09:27:05-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:27:06 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 34098. Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=info msg="zeroconf server listening on port 39645" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:27:06 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jun 01 09:27:06 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jun 01 09:27:06 volumio systemd[1]: volumio.service: Consumed 15.503s CPU time. Jun 01 09:27:06 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jun 01 09:27:06 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=debug msg="obtained new client token: AABMEsiqariw+IAAl2D/Zs/iMYJx+pGbFozsqi4l0xCYL59rL7Y19O6fDGt3tyq0R5sx/WWuYziNbjKNjMCI8jwMcjxSF01UX1hA84Pzszgv0BlZF7UmQh6042S881/EUn2OOdg/Ko+PhbJRvHiuJGL0GPHzA7eMZ+MvRi8hrRziVKQNF2oIhcsTAVQ90Jj8BDV/y1hy5aZeAhE3209ocCwFk5k9PphNe4WCK6KENt8nX5Yvdaq0gJsABw==" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=debug msg="completed challenge" Jun 01 09:27:06 volumio go-librespot[27518]: time="2026-06-01T09:27:06-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:06 volumio volumio5-onboarding[21559]: time=2026-06-01T09:27:06.830-04:00 level=WARN msg="reconnection attempt failed" component=volumio/socket error="dial tcp 127.0.0.1:3000: connect: connection refused" Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=debug msg="completed challenge" Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:07 volumio volumio[27534]: info: ------------------------------------------- Jun 01 09:27:07 volumio volumio[27534]: info: ----- Volumio3 ---- Jun 01 09:27:07 volumio volumio[27534]: info: ------------------------------------------- Jun 01 09:27:07 volumio volumio[27534]: info: ----- System startup ---- Jun 01 09:27:07 volumio volumio[27534]: info: ------------------------------------------- Jun 01 09:27:07 volumio volumio[27534]: info: MYVOLUMIO Environment detected Jun 01 09:27:07 volumio volumio[27534]: info: Plugin folders cleanup Jun 01 09:27:07 volumio volumio[27534]: info: Scanning into folder /volumio/app/plugins/ Jun 01 09:27:07 volumio volumio[27534]: info: Scanning category audio_interface Jun 01 09:27:07 volumio volumio[27534]: info: Scanning category miscellanea Jun 01 09:27:07 volumio volumio[27534]: info: Scanning category music_service Jun 01 09:27:07 volumio volumio[27534]: info: Scanning category plugins.json Jun 01 09:27:07 volumio volumio[27534]: info: Scanning category system_controller Jun 01 09:27:07 volumio volumio[27534]: info: Scanning category user_interface Jun 01 09:27:07 volumio volumio[27534]: info: Scanning into folder /data/plugins/ Jun 01 09:27:07 volumio volumio[27534]: info: Scanning category music_service Jun 01 09:27:07 volumio volumio[27534]: info: Plugin folders cleanup completed Jun 01 09:27:07 volumio volumio[27534]: info: ------------------------------------------- Jun 01 09:27:07 volumio volumio[27534]: info: ----- Core plugins startup ---- Jun 01 09:27:07 volumio volumio[27534]: info: ------------------------------------------- Jun 01 09:27:07 volumio volumio[27534]: info: Loading plugins from folder /volumio/app/plugins/ Jun 01 09:27:07 volumio volumio[27534]: info: Adding plugin upnp to MyMusic Plugins Jun 01 09:27:07 volumio volumio[27534]: info: Adding plugin airplay_emulation to MyMusic Plugins Jun 01 09:27:07 volumio volumio[27534]: info: Adding plugin upnp_browser to MyMusic Plugins Jun 01 09:27:07 volumio volumio[27534]: info: Loading plugins from folder /data/plugins/ Jun 01 09:27:07 volumio volumio[27534]: info: Loading plugin "system"... Jun 01 09:27:07 volumio volumio[27534]: info: Loading plugin "appearance"... Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=debug msg="completed challenge" Jun 01 09:27:07 volumio go-librespot[27518]: time="2026-06-01T09:27:07-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "network"... Jun 01 09:27:08 volumio volumio[27534]: info: Refreshing Cached IP Addresses Jun 01 09:27:08 volumio sudo[27562]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:27:08 volumio sudo[27562]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:08 volumio sudo[27564]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:27:08 volumio sudo[27564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:08 volumio sudo[27562]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "services"... Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "volumio5onboarding"... Jun 01 09:27:08 volumio sudo[27564]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "alsa_controller"... Jun 01 09:27:08 volumio sudo[27573]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jun 01 09:27:08 volumio sudo[27573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:08 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "wizard"... Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "networkfs"... Jun 01 09:27:08 volumio go-librespot[27518]: time="2026-06-01T09:27:08-04:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jun 01 09:27:08 volumio volumio[27534]: info: Starting Udev Watcher for removable devices Jun 01 09:27:08 volumio volumio[27534]: info: Ignoring mount for partition: boot Jun 01 09:27:08 volumio volumio[27534]: info: Ignoring mount for partition: volumio Jun 01 09:27:08 volumio volumio[27534]: info: Ignoring mount for partition: volumio_data Jun 01 09:27:08 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "volumio_command_line_client"... Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "upnp"... Jun 01 09:27:08 volumio volumio[27534]: info: [1780320428467] Starting Upmpd Daemon Jun 01 09:27:08 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "my_music"... Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "mpd"... Jun 01 09:27:08 volumio go-librespot[27518]: time="2026-06-01T09:27:08-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:08 volumio go-librespot[27518]: time="2026-06-01T09:27:08-04:00" level=debug msg="completed challenge" Jun 01 09:27:08 volumio go-librespot[27518]: time="2026-06-01T09:27:08-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:08 volumio volumio[27534]: info: Loading plugin "upnp_browser"... Jun 01 09:27:09 volumio go-librespot[27518]: time="2026-06-01T09:27:09-04:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jun 01 09:27:09 volumio go-librespot[27518]: time="2026-06-01T09:27:09-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.40.94:40068->104.199.65.9:443: read: connection reset by peer" Jun 01 09:27:09 volumio volumio[27534]: info: Starting UPNP Browser Jun 01 09:27:09 volumio volumio[27534]: info: Loading plugin "alarm-clock"... Jun 01 09:27:09 volumio volumio[27534]: info: Loading plugin "airplay_emulation"... Jun 01 09:27:09 volumio volumio[27534]: info: Starting Shairport Sync Jun 01 09:27:09 volumio volumio[27534]: info: Loading plugin "last_100"... Jun 01 09:27:09 volumio volumio[27534]: info: Loading plugin "webradio"... Jun 01 09:27:09 volumio volumio[27534]: info: Loading plugin "i2s_dacs"... Jun 01 09:27:09 volumio volumio[27534]: info: Loading plugin "volumiodiscovery"... Jun 01 09:27:09 volumio volumio[27534]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:27:09 volumio volumio[27534]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:27:09 volumio volumio[27534]: *** WARNING *** For more information see Jun 01 09:27:09 volumio volumio[27534]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:27:09 volumio volumio[27534]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:27:09 volumio node[27534]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jun 01 09:27:09 volumio volumio[27534]: *** WARNING *** For more information see Jun 01 09:27:09 volumio node[27534]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:27:09 volumio node[27534]: *** WARNING *** For more information see Jun 01 09:27:09 volumio node[27534]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jun 01 09:27:09 volumio node[27534]: *** WARNING *** Please fix your application to use the native API of Avahi! Jun 01 09:27:09 volumio node[27534]: *** WARNING *** For more information see Jun 01 09:27:09 volumio volumio[27534]: info: Applying required configuration parameters for plugin volumiodiscovery Jun 01 09:27:09 volumio volumio[27534]: info: Discovery: Started advertising with name: Volumio Jun 01 09:27:09 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jun 01 09:27:09 volumio volumio[27534]: info: Loading plugin "spop"... Jun 01 09:27:09 volumio go-librespot[27518]: time="2026-06-01T09:27:09-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:27:10 volumio go-librespot[27518]: time="2026-06-01T09:27:10-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:10 volumio go-librespot[27518]: time="2026-06-01T09:27:10-04:00" level=debug msg="completed challenge" Jun 01 09:27:10 volumio volumio[27534]: info: Loading plugin "outputs"... Jun 01 09:27:10 volumio volumio[27534]: info: Loading plugin "albumart"... Jun 01 09:27:10 volumio go-librespot[27518]: time="2026-06-01T09:27:10-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:10 volumio go-librespot[27518]: time="2026-06-01T09:27:10-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:10 volumio volumio[27534]: info: Plugin example_plugin is not enabled Jun 01 09:27:10 volumio volumio[27534]: info: Loading plugin "inputs"... Jun 01 09:27:10 volumio volumio[27534]: info: Loading plugin "updater_comm"... Jun 01 09:27:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:27:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:27:10 volumio volumio[27534]: info: Plugin mpdemulation is not enabled Jun 01 09:27:10 volumio volumio[27534]: info: Loading plugin "rest_api"... Jun 01 09:27:10 volumio volumio[27534]: info: Loading plugin "websocket"... Jun 01 09:27:10 volumio volumio[27534]: info: Starting Socket.io Server version 1.7.4 Jun 01 09:27:10 volumio volumio[27534]: info: Loading i18n strings for locale en Jun 01 09:27:10 volumio volumio[27534]: Updating browse sources language Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::initPlayerControls Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: Express server listening on port 3000 Jun 01 09:27:10 volumio volumio[27534]: [Metrics] WebUI: 3s 384.18ms Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::resetVolumioState Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::getcurrentVolume Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:27:10 volumio volumio[27534]: info: Volumio Network Manager: Network status updated: 1 Jun 01 09:27:10 volumio volumio[27534]: 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 Jun 01 09:27:10 volumio volumio[27597]: Forking 3 albumart workers Jun 01 09:27:10 volumio volumio[27534]: 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 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: Reloading queue from file Jun 01 09:27:10 volumio volumio[27534]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::pushState Jun 01 09:27:10 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioPushState Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::updateTrackBlock Jun 01 09:27:10 volumio volumio[27534]: info: CorePlayQueue::getTrackBlock Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioRetrievevolume Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::setRepeat null single undefined Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::pushState Jun 01 09:27:10 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioPushState Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::setRandom null Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::pushState Jun 01 09:27:10 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioPushState Jun 01 09:27:10 volumio volumio[27534]: info: Setting Device type: Raspberry PI Jun 01 09:27:10 volumio volumio[27534]: info: Completed loading Core Plugins Jun 01 09:27:10 volumio volumio[27534]: info: Preparing to generate the ALSA configuration file Jun 01 09:27:10 volumio volumio[27534]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Jun 01 09:27:10 volumio volumio[27534]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Jun 01 09:27:10 volumio volumio[27534]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Jun 01 09:27:10 volumio volumio[27534]: 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 Jun 01 09:27:10 volumio volumio[27534]: 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 Jun 01 09:27:10 volumio volumio[27534]: info: VolumeController:: Volume=33 Mute =false Jun 01 09:27:10 volumio volumio[27534]: info: CoreStateMachine::pushState Jun 01 09:27:10 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioPushState Jun 01 09:27:10 volumio volumio[27534]: info: Asound.conf file unchanged, so no further update is needed Jun 01 09:27:10 volumio volumio[27534]: info: Output device has changed, restarting MPD Jun 01 09:27:10 volumio volumio[27534]: info: Output device has changed, restarting Shairport Sync Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:10 volumio sudo[27653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:27:10 volumio sudo[27653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:10 volumio sudo[27653]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:10 volumio sudo[27654]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:27:10 volumio volumio[27534]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:27:10 volumio volumio[27534]: info: ___________ START PLUGINS ___________ Jun 01 09:27:10 volumio volumio[27534]: info: ControllerMpd::onStart: Initializing MPD Jun 01 09:27:10 volumio volumio[27534]: info: Creating MPD Configuration file Jun 01 09:27:10 volumio sudo[27654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:10 volumio sudo[27661]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service Jun 01 09:27:10 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jun 01 09:27:10 volumio sudo[27661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:27:10 volumio volumio[27534]: info: [1780320430760] CoreMusicLibrary::Adding element Media Servers Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:27:10 volumio sudo[27664]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 01 09:27:10 volumio sudo[27664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:10 volumio volumio[27534]: info: UPNP Browser: Client initialized successfully Jun 01 09:27:10 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 01 09:27:10 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 09:27:10 volumio systemd[1]: mpd.service: Consumed 1.923s CPU time. Jun 01 09:27:10 volumio sudo[27664]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:10 volumio sudo[27667]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:10 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 01 09:27:10 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 09:27:10 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 09:27:10 volumio sudo[27667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:10 volumio volumio[27534]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:10 volumio volumio-remote-updater[761]: [2026-06-01 09:27:10] [connect] Successful connection Jun 01 09:27:10 volumio volumio[27534]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:27:10 volumio volumio[27534]: info: [1780320430845] CoreMusicLibrary::Adding element Last_100 Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:27:10 volumio volumio[27534]: info: [1780320430847] CoreMusicLibrary::Adding element Webradio Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:27:10 volumio volumio[27534]: info: Initializing BBC Radios Jun 01 09:27:10 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 09:27:10 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 09:27:10 volumio sudo[27661]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:10 volumio systemd[1]: mpd.service: Deactivated successfully. Jun 01 09:27:10 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jun 01 09:27:10 volumio systemd[1]: mpd.socket: Deactivated successfully. Jun 01 09:27:10 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jun 01 09:27:10 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jun 01 09:27:10 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:10 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jun 01 09:27:10 volumio volumio[27534]: info: Creating Spotify config file Jun 01 09:27:10 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio sudo[27695]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 01 09:27:11 volumio sudo[27695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 01 09:27:11 volumio sudo[27695]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:11 volumio volumio[27534]: info: Volumio Calling Home Jun 01 09:27:11 volumio sudo[27573]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:11 volumio volumio[27534]: 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 Jun 01 09:27:11 volumio volumio[27534]: info: Discovery: adding 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:27:11 volumio volumio[27534]: info: Discovery: Found device Volumio Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::volumioGetState Jun 01 09:27:11 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:11 volumio volumio[27534]: info: MPD Permissions set Jun 01 09:27:11 volumio volumio[27534]: info: MPD Permissions set Jun 01 09:27:11 volumio volumio-remote-updater[761]: [2026-06-01 09:27:11] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1780320430 101 Jun 01 09:27:11 volumio volumio[27534]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jun 01 09:27:11 volumio volumio[27534]: info: Spotify config file written Jun 01 09:27:11 volumio volumio[27534]: info: Discovery: this is already registered, 06bc7e56-8b79-4cef-9be9-937c85882959 Jun 01 09:27:11 volumio volumio[27534]: info: Discovery: Found device Volumio Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::volumioGetState Jun 01 09:27:11 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:11 volumio volumio[27534]: 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: 2 Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio sudo[27702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 01 09:27:11 volumio sudo[27702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:11 volumio volumio[27616]: Starting albumart workers Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 01 09:27:11 volumio volumio[27534]: info: No need to fix Spotify hosts Jun 01 09:27:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:27:11 volumio go-librespot[27710]: go-librespot daemon starting... Jun 01 09:27:11 volumio go-librespot[27715]: time="2026-06-01T09:27:11-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:27:11 volumio go-librespot[27715]: time="2026-06-01T09:27:11-04:00" level=debug msg="app state loaded" Jun 01 09:27:11 volumio volumio[27534]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jun 01 09:27:11 volumio sudo[27702]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:11 volumio go-librespot[27715]: time="2026-06-01T09:27:11-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:27:11 volumio volumio[27628]: Starting albumart workers Jun 01 09:27:11 volumio volumio[27534]: 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: 3 Jun 01 09:27:11 volumio volumio[27534]: info: Volumio called home Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:27:12 volumio volumio[27534]: info: Starting Shairport Sync Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=info msg="zeroconf server listening on port 43953" Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:27:12 volumio volumio[27534]: info: Starting Shairport Sync Jun 01 09:27:12 volumio volumio[27534]: info: Starting Shairport Sync Jun 01 09:27:12 volumio volumio[27534]: info: New Spotify access tokenBQByo33OX7... Jun 01 09:27:12 volumio volumio[27534]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 01 09:27:12 volumio sudo[27732]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:27:12 volumio sudo[27732]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:12 volumio sudo[27736]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:27:12 volumio sudo[27736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:12 volumio sudo[27734]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jun 01 09:27:12 volumio sudo[27734]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=debug msg="obtained new client token: AADxKL+LVbtQ3MHPlPxs2OP5xUmdckAZErYrPR2kqgVk4mQBwwR0Dw9w5gWDobslhuU/gxaGfYrul3Xz5cndvpqTVE9gqRhSUzQ0alZ8Oc/mM1MNfN/+w9i2RLLBir8eYgnfzKWYambkMwzcqN1CFpMaN17RT7fDhyy1vW7fmHiecVzhB17Mw4vktgg+eAJIWsX1SP/R6MGHTQ752GhH3tLXurY6tL6rr/CVFtzrYtVNXG2m5NnQjDI=" Jun 01 09:27:12 volumio volumio[27534]: 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: 3 Jun 01 09:27:12 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jun 01 09:27:12 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jun 01 09:27:12 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:27:12 volumio systemd[1]: shairport-sync.service: Consumed 1.658s CPU time. Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:27:12 volumio volumio[27618]: Starting albumart workers Jun 01 09:27:12 volumio volumio[27534]: 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: 3 Jun 01 09:27:12 volumio volumio[27534]: info: Received Get System Info Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 01 09:27:12 volumio volumio[27534]: info: Discovery: Getting this device information Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::volumioGetState Jun 01 09:27:12 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jun 01 09:27:12 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jun 01 09:27:12 volumio sudo[27734]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:12 volumio sudo[27736]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:12 volumio sudo[27732]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=debug msg="completed challenge" Jun 01 09:27:12 volumio go-librespot[27715]: time="2026-06-01T09:27:12-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:12 volumio volumio[27534]: info: Shairport-Sync Started Jun 01 09:27:12 volumio volumio[27534]: Error adding Membership: Error: addMembership EINVAL Jun 01 09:27:12 volumio volumio[27534]: info: Shairport-Sync Started Jun 01 09:27:12 volumio volumio[27534]: info: Shairport-Sync Started Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::volumioGetState Jun 01 09:27:12 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:12 volumio volumio[27534]: SPOTIFY: User informations: {"account_id":"W4wCmVA8pZ","country":"US","display_name":"122559042","email":"jarrod@higginscomputer.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/122559042"},"followers":{"href":null,"total":3},"href":"https://api.spotify.com/v1/users/122559042","id":"122559042","images":[],"product":"premium","type":"user","uri":"spotify:user:122559042"} Jun 01 09:27:12 volumio volumio[27534]: info: Spotify Successfully logged in Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 01 09:27:12 volumio volumio[27534]: info: [1780320432666] CoreMusicLibrary::Adding element Spotify Jun 01 09:27:12 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 01 09:27:12 volumio volumio[27534]: Cannot find translation for source Spotify Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=debug msg="completed challenge" Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:13 volumio mpd[27697]: 2026-06-01T09:27:13 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 01 09:27:13 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jun 01 09:27:13 volumio sudo[27667]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:13 volumio sudo[27654]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:13 volumio volumio[27534]: info: Completed starting Core Plugins Jun 01 09:27:13 volumio volumio[27534]: info: ------------------------------------------- Jun 01 09:27:13 volumio volumio[27534]: info: ----- MyVolumio plugins startup ---- Jun 01 09:27:13 volumio volumio[27534]: info: ------------------------------------------- Jun 01 09:27:13 volumio volumio[27534]: info: [MyVolumio PluginManager] Fetching plans data.... Jun 01 09:27:13 volumio volumio[27534]: error: MPD error: The expression evaluated to a falsy value: Jun 01 09:27:13 volumio volumio[27534]: assert.ok(self.idling) Jun 01 09:27:13 volumio volumio[27534]: error: The expression evaluated to a falsy value: Jun 01 09:27:13 volumio volumio[27534]: assert.ok(self.idling) Jun 01 09:27:13 volumio volumio[27534]: error: updateQueue error: null Jun 01 09:27:13 volumio volumio[27534]: info: MPD running with PID27697 Jun 01 09:27:13 volumio volumio[27534]: ,establishing connection Jun 01 09:27:13 volumio volumio[27534]: error: updateQueue error: null Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=debug msg="completed challenge" Jun 01 09:27:13 volumio go-librespot[27715]: time="2026-06-01T09:27:13-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:14 volumio go-librespot[27715]: time="2026-06-01T09:27:14-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:27:14 volumio go-librespot[27715]: time="2026-06-01T09:27:14-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:14 volumio go-librespot[27715]: time="2026-06-01T09:27:14-04:00" level=debug msg="completed challenge" Jun 01 09:27:14 volumio go-librespot[27715]: time="2026-06-01T09:27:14-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:14 volumio volumio[27534]: info: go-librespot daemon successfully initialized Jun 01 09:27:15 volumio go-librespot[27715]: time="2026-06-01T09:27:15-04:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jun 01 09:27:15 volumio go-librespot[27715]: time="2026-06-01T09:27:15-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.40.94:58364->104.199.65.9:443: read: connection reset by peer" Jun 01 09:27:16 volumio go-librespot[27715]: time="2026-06-01T09:27:16-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:27:16 volumio go-librespot[27715]: time="2026-06-01T09:27:16-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:16 volumio go-librespot[27715]: time="2026-06-01T09:27:16-04:00" level=debug msg="completed challenge" Jun 01 09:27:16 volumio go-librespot[27715]: time="2026-06-01T09:27:16-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:16 volumio go-librespot[27715]: time="2026-06-01T09:27:16-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:27:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:27:17 volumio volumio[27534]: info: Initializing connection to go-librespot Websocket Jun 01 09:27:17 volumio volumio[27534]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jun 01 09:27:18 volumio volumio[27534]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jun 01 09:27:18 volumio sudo[27787]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 01 09:27:18 volumio sudo[27787]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:18 volumio sudo[27787]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:18 volumio sudo[27789]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 01 09:27:18 volumio sudo[27789]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:18 volumio sudo[27789]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:18 volumio sudo[27792]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jun 01 09:27:18 volumio sudo[27792]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:18 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Jun 01 09:27:18 volumio sudo[27792]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:18 volumio volumio[27534]: info: Upmpdcli Daemon Started Jun 01 09:27:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jun 01 09:27:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:27:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jun 01 09:27:19 volumio go-librespot[27816]: go-librespot daemon starting... Jun 01 09:27:19 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully. Jun 01 09:27:19 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=info msg="running go-librespot 0.7.1" Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=debug msg="app state loaded" Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=info msg="zeroconf server listening on port 40679" Jun 01 09:27:19 volumio go-librespot[27820]: time="2026-06-01T09:27:19-04:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="obtained new client token: AABoJtZAbYLsV+CgocpxCHc2bkanwebtn7o5+odH2OePYbzFiBrnbax7989CPYckSK5q2DSiGTosLqUtreNt5aRk8W4EDtJkAPUs9osuvD2lJxfO0wurh2Rhyv9h0Vv9oIcjoHlvi/Cv4/rhEBDEXzi1y3Uw6v/CWV8GhMpVDcTmo+O3hnLc93Z/6/e7gSPe7d3NankFPINyTs9tB/raurwWeBLbv2Hp2rzYsLifg0vnfuoY45q+0FU=" Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="completed challenge" Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="completed challenge" Jun 01 09:27:20 volumio volumio[27534]: info: Initializing connection to go-librespot Websocket Jun 01 09:27:20 volumio volumio[27534]: info: Connection to go-librespot Websocket established Jun 01 09:27:20 volumio go-librespot[27820]: time="2026-06-01T09:27:20-04:00" level=debug msg="new websocket client" Jun 01 09:27:21 volumio go-librespot[27820]: time="2026-06-01T09:27:21-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jun 01 09:27:21 volumio volumio[27534]: info: Adding plugin bluetooth to MyMusic Plugins Jun 01 09:27:21 volumio volumio[27534]: info: Adding plugin multiroom to MyMusic Plugins Jun 01 09:27:21 volumio volumio[27534]: info: Adding plugin metavolumio to MyMusic Plugins Jun 01 09:27:21 volumio volumio[27534]: info: Adding plugin cd_controller to MyMusic Plugins Jun 01 09:27:21 volumio volumio[27534]: info: Adding plugin qobuzconnect to MyMusic Plugins Jun 01 09:27:21 volumio volumio[27534]: info: Adding plugin smart_inputs to MyMusic Plugins Jun 01 09:27:21 volumio volumio[27534]: info: Adding plugin tidalconnect to MyMusic Plugins Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jun 01 09:27:21 volumio go-librespot[27820]: time="2026-06-01T09:27:21-04:00" level=debug msg="connected to ap-guc3.spotify.com:80" Jun 01 09:27:21 volumio go-librespot[27820]: time="2026-06-01T09:27:21-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:21 volumio go-librespot[27820]: time="2026-06-01T09:27:21-04:00" level=debug msg="completed challenge" Jun 01 09:27:21 volumio go-librespot[27820]: time="2026-06-01T09:27:21-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jun 01 09:27:21 volumio volumio[27534]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jun 01 09:27:21 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:21 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:21 volumio volumio[27534]: info: Starting MyVolumio Remote Streaming Endpoints Jun 01 09:27:22 volumio volumio[27534]: info: MyVolumio login type: Token Jun 01 09:27:22 volumio volumio[27534]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jun 01 09:27:22 volumio volumio[27534]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jun 01 09:27:22 volumio go-librespot[27820]: time="2026-06-01T09:27:22-04:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jun 01 09:27:22 volumio volumio[27534]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 01 09:27:22 volumio volumio[27534]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 01 09:27:22 volumio volumio[27534]: info: Streaming services startup Jun 01 09:27:22 volumio volumio[27534]: info: Starting Streaming Daemon Jun 01 09:27:22 volumio sudo[27831]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:27:22 volumio sudo[27831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:22 volumio volumio[27534]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 01 09:27:22 volumio sudo[27831]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:22 volumio volumio[27534]: error: Cannot start Volumio Streaming Daemon Jun 01 09:27:22 volumio volumio[27534]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:27:22 volumio volumio[27534]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:27:22 volumio go-librespot[27820]: time="2026-06-01T09:27:22-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:22 volumio go-librespot[27820]: time="2026-06-01T09:27:22-04:00" level=debug msg="completed challenge" Jun 01 09:27:22 volumio go-librespot[27820]: time="2026-06-01T09:27:22-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:22 volumio volumio[27534]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 01 09:27:23 volumio go-librespot[27820]: time="2026-06-01T09:27:23-04:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jun 01 09:27:23 volumio go-librespot[27820]: time="2026-06-01T09:27:23-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:23 volumio go-librespot[27820]: time="2026-06-01T09:27:23-04:00" level=debug msg="completed challenge" Jun 01 09:27:23 volumio volumio[27534]: info: MyVolumio token set successfully Jun 01 09:27:23 volumio volumio[27534]: info: MYVOLUMIO: Adding device Jun 01 09:27:23 volumio volumio[27534]: info: MYVOLUMIO: Evaluating Server Jun 01 09:27:23 volumio go-librespot[27820]: time="2026-06-01T09:27:23-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:23 volumio volumio[27534]: info: MyVolumio status changed Jun 01 09:27:23 volumio volumio[27534]: info: Streaming services startup Jun 01 09:27:23 volumio volumio[27534]: info: Starting Streaming Daemon Jun 01 09:27:23 volumio volumio[27534]: info: Removing browser output: myVolumio user plan is not superstar Jun 01 09:27:23 volumio volumio[27534]: info: Removing audio output: Jun 01 09:27:23 volumio volumio[27534]: info: Stoppping Tunnel 1 Jun 01 09:27:23 volumio sudo[27858]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 01 09:27:23 volumio sudo[27858]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:23 volumio sudo[27860]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jun 01 09:27:23 volumio sudo[27860]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 01 09:27:23 volumio sudo[27858]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:23 volumio volumio[27534]: error: Cannot start Volumio Streaming Daemon Jun 01 09:27:23 volumio volumio[27534]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 01 09:27:23 volumio volumio[27534]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Jun 01 09:27:23 volumio sudo[27860]: pam_unix(sudo:session): session closed for user root Jun 01 09:27:23 volumio volumio[27534]: info: Remote SSH Stopped Jun 01 09:27:24 volumio volumio[27534]: info: Getting Spotify volume Jun 01 09:27:24 volumio volumio[27534]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jun 01 09:27:24 volumio volumio[27534]: info: CoreCommandRouter::volumioGetState Jun 01 09:27:24 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:24 volumio volumio[27534]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Jun 01 09:27:24 volumio volumio[27534]: SPOTIFY: SPOTIFY VOLUME undefined Jun 01 09:27:24 volumio volumio[27534]: SPOTIFY: VOLUMIO VOLUME 33 Jun 01 09:27:24 volumio volumio[27534]: info: Aligning Spotify Volume to Volumio Volume Jun 01 09:27:24 volumio volumio[27534]: info: CoreCommandRouter::volumioGetState Jun 01 09:27:24 volumio volumio[27534]: info: CorePlayQueue::getTrack 0 Jun 01 09:27:24 volumio volumio[27534]: info: Setting Spotify Volume from Volumio: 33 Jun 01 09:27:24 volumio volumio[27534]: info: Setting Geolocation for MyVolumio to us1 Jun 01 09:27:24 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:24 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:24 volumio volumio[27534]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 01 09:27:24 volumio go-librespot[27820]: time="2026-06-01T09:27:24-04:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jun 01 09:27:24 volumio volumio[27534]: info: Successfully Added MyVolumio device Jun 01 09:27:24 volumio go-librespot[27820]: time="2026-06-01T09:27:24-04:00" level=debug msg="completed keyexchange" Jun 01 09:27:24 volumio go-librespot[27820]: time="2026-06-01T09:27:24-04:00" level=debug msg="completed challenge" Jun 01 09:27:24 volumio go-librespot[27820]: time="2026-06-01T09:27:24-04:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:24 volumio go-librespot[27820]: time="2026-06-01T09:27:24-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Jun 01 09:27:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jun 01 09:27:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jun 01 09:27:24 volumio volumio[27534]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:27:24 volumio volumio[27534]: Error: socket hang up Jun 01 09:27:24 volumio volumio[27534]: at connResetException (node:internal/errors:720:14) Jun 01 09:27:24 volumio volumio[27534]: at Socket.socketOnEnd (node:_http_client:519:23) Jun 01 09:27:24 volumio volumio[27534]: at Socket.emit (node:events:526:35) Jun 01 09:27:24 volumio volumio[27534]: at endReadableNT (node:internal/streams/readable:1376:12) Jun 01 09:27:24 volumio volumio[27534]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jun 01 09:27:24 volumio volumio[27534]: code: 'ECONNRESET', Jun 01 09:27:24 volumio volumio[27534]: response: undefined Jun 01 09:27:24 volumio volumio[27534]: } Jun 01 09:27:24 volumio volumio[27534]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 01 09:27:25 volumio sudo[27877]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-06-01 09:26' Jun 01 09:27:25 volumio sudo[27877]: 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"