Dec 06 16:50:00 volumio volumio[14232]: info: Applying required configuration parameters for plugin volusonic Dec 06 16:50:00 volumio volumio[14232]: info: Loading plugin "backup_restore"... Dec 06 16:50:00 volumio volumio[14343]: Starting albumart workers Dec 06 16:50:00 volumio volumio[14341]: Starting albumart workers Dec 06 16:50:00 volumio volumio[14342]: Starting albumart workers Dec 06 16:50:00 volumio volumio[14232]: info: Applying required configuration parameters for plugin backup_restore Dec 06 16:50:00 volumio volumio[14232]: info: Plugin rpi_eeprom_config is not enabled Dec 06 16:50:00 volumio volumio[14232]: info: Plugin rpi_eeprom_updater is not enabled Dec 06 16:50:00 volumio volumio[14232]: info: Loading plugin "scheduledrestart"... Dec 06 16:50:00 volumio volumio[14232]: info: Applying required configuration parameters for plugin scheduledrestart Dec 06 16:50:00 volumio volumio[14232]: info: Plugin Bluetoothremote is not enabled Dec 06 16:50:00 volumio volumio[14232]: info: Plugin music_services_shield is not enabled Dec 06 16:50:00 volumio volumio[14232]: info: Loading plugin "Systeminfo"... Dec 06 16:50:01 volumio volumio[14232]: info: Plugin peppymeterbasic is not enabled Dec 06 16:50:01 volumio volumio[14232]: info: Loading plugin "peppyspectrum"... Dec 06 16:50:01 volumio volumio[14232]: info: Loading i18n strings for locale en Dec 06 16:50:01 volumio volumio[14232]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:50:01 volumio volumio[14232]: Updating browse sources language Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::initPlayerControls Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:01 volumio volumio[14232]: Express server listening on port 3000 Dec 06 16:50:01 volumio volumio[14232]: [Metrics] WebUI: 14s 648.87ms Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::resetVolumioState Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::getcurrentVolume Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:01 volumio sudo[14416]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 16:50:01 volumio sudo[14416]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:01 volumio sudo[14418]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 16:50:01 volumio sudo[14418]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:01 volumio sudo[14418]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:01 volumio sudo[14416]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:01 volumio volumio[14232]: info: Volumio Network Manager: Network status updated: 1 Dec 06 16:50:01 volumio volumio[14232]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::pushState Dec 06 16:50:01 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::updateTrackBlock Dec 06 16:50:01 volumio volumio[14232]: info: CorePlayQueue::getTrackBlock Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:50:01 volumio volumio[14232]: info: Reloading queue from file Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::setRepeat null single undefined Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::pushState Dec 06 16:50:01 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::setRandom null Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::pushState Dec 06 16:50:01 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:01 volumio volumio[14232]: info: Setting Device type: Raspberry PI Dec 06 16:50:01 volumio volumio[14232]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:50:01 volumio volumio[14232]: info: CoreStateMachine::pushState Dec 06 16:50:01 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:01 volumio volumio[14232]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:01 volumio volumio[14232]: info: Completed loading Core Plugins Dec 06 16:50:01 volumio volumio[14232]: info: Preparing to generate the ALSA configuration file Dec 06 16:50:01 volumio sudo[14431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 06 16:50:01 volumio sudo[14431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:02 volumio volumio[14232]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:50:02 volumio volumio[14232]: info: Discovery: Found device Volumio Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:02 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:02 volumio volumio[14232]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:50:02 volumio volumio[14232]: info: Discovery: Found device Volumio Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:02 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:02 volumio volumio[14232]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:50:02 volumio volumio[14232]: info: Reading ALSA contributions from plugins. Dec 06 16:50:02 volumio sudo[14431]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:02 volumio volumio[14232]: info: Upmpdcli Daemon Started Dec 06 16:50:02 volumio volumio[14232]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:50:02 volumio volumio[14232]: info: Output device has changed, restarting MPD Dec 06 16:50:02 volumio volumio[14232]: info: Output device has changed, restarting Shairport Sync Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:02 volumio sudo[14434]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:50:02 volumio sudo[14434]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:02 volumio sudo[14434]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:02 volumio sudo[14436]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:50:02 volumio sudo[14436]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:02 volumio volumio[14232]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:02 volumio volumio[14232]: info: ___________ START PLUGINS ___________ Dec 06 16:50:02 volumio volumio[14232]: info: ControllerMpd::onStart: Initializing MPD Dec 06 16:50:02 volumio volumio[14232]: info: Creating MPD Configuration file Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402134] CoreMusicLibrary::Adding element Media Servers Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 06 16:50:02 volumio sudo[14446]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:50:02 volumio sudo[14446]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:02 volumio sudo[14445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:50:02 volumio sudo[14445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:02 volumio sudo[14445]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:02 volumio volumio[14232]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:02 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:50:02 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:50:02 volumio systemd[1]: mpd.service: Consumed 4.602s CPU time. Dec 06 16:50:02 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:50:02 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:50:02 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:50:02 volumio volumio[14232]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402270] CoreMusicLibrary::Adding element Last_100 Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402275] CoreMusicLibrary::Adding element Webradio Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:50:02 volumio volumio[14232]: info: Initializing BBC Radios Dec 06 16:50:02 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:50:02 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402356] CoreMusicLibrary::Adding element Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402368] CoreMusicLibrary::Adding element SoundCloud Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:02 volumio volumio[14232]: info: Creating Spotify config file Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:02 volumio sudo[14468]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:50:02 volumio sudo[14468]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:50:02 volumio sudo[14468]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:02 volumio volumio-remote-updater[2353]: [2025-12-06 16:50:02] [connect] Successful connection Dec 06 16:50:02 volumio volumio[14232]: info: [squeezelite_mc] Starting proxy server... Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402724] CoreMusicLibrary::Adding element YouTube2 Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube2 Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402743] CoreMusicLibrary::Adding element YouTube Music Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube2 Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube Music Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402755] CoreMusicLibrary::Adding element Podcast Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube2 Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube Music Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Podcast Dec 06 16:50:02 volumio volumio[14232]: info: Loading i18n strings for locale en Dec 06 16:50:02 volumio volumio[14232]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:50:02 volumio volumio[14232]: Updating browse sources language Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube2 Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube Music Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Podcast Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube2 Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube Music Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Podcast Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:02 volumio volumio[14232]: info: [1765061402802] CoreMusicLibrary::Adding element Volusonic Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube2 Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source YouTube Music Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Podcast Dec 06 16:50:02 volumio volumio[14232]: Cannot find translation for source Volusonic Dec 06 16:50:02 volumio volumio[14232]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 06 16:50:02 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 06 16:50:02 volumio volumio[14232]: info: Volumio Calling Home Dec 06 16:50:02 volumio volumio[14232]: info: [squeezelite_mc] Proxy server started on port 45169 Dec 06 16:50:02 volumio volumio[14232]: info: Preparing to generate the ALSA configuration file Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:50:03 volumio volumio[14232]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:50:03 volumio volumio[14232]: info: Reading ALSA contributions from plugins. Dec 06 16:50:03 volumio volumio[14232]: info: MPD Permissions set Dec 06 16:50:03 volumio volumio[14232]: info: MPD Permissions set Dec 06 16:50:03 volumio volumio-remote-updater[2353]: [2025-12-06 16:50:03] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765061402 101 Dec 06 16:50:03 volumio volumio[14232]: 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 Dec 06 16:50:03 volumio volumio[14232]: info: Spotify config file written Dec 06 16:50:03 volumio sudo[14481]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 06 16:50:03 volumio sudo[14481]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 06 16:50:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:03 volumio volumio[14232]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 06 16:50:03 volumio volumio[14232]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:50:03 volumio volumio[14232]: info: CoreStateMachine::pushState Dec 06 16:50:03 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:03 volumio volumio[14232]: info: [squeezelite_mc] Server discovery started Dec 06 16:50:03 volumio volumio[14232]: info: [squeezelite_mc] Player finder started Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:03 volumio go-librespot[14483]: go-librespot daemon starting... Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 06 16:50:03 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 06 16:50:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:03 volumio volumio[14232]: info: No need to fix Spotify hosts Dec 06 16:50:03 volumio sudo[14481]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:03 volumio go-librespot[14502]: go-librespot daemon starting... Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=debug msg="app state loaded" Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:03 volumio volumio[14232]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 06 16:50:03 volumio volumio[14232]: info: Volumio called home Dec 06 16:50:03 volumio volumio[14232]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"} Dec 06 16:50:03 volumio volumio[14232]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 06 16:50:03 volumio volumio[14232]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 06 16:50:03 volumio volumio[14232]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:50:03 volumio volumio[14232]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:50:03 volumio volumio[14232]: SPOTIFY: BQDkwzsgHHp-wdrQh0WiGnnUQhzAXQZwhGfHIqSQcNgPdI0m8dNAfVslLj1FOsq53m41NnM7yk1HZPHor0TW0yB9PCsSnSarTV3PcjOAshaqlqycjOZrIuin7tX3SFlaaxOCm87-apezE1MFdk3PtBy1jTbbe43XR8_RtwBRO5Nwo7NfyHmglpz3874TsCVVVAMIFUycQ8jY_yLdA4k47462NfUE_Qo_57WmRvk Dec 06 16:50:03 volumio volumio[14232]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:50:03 volumio volumio[14232]: info: New Spotify access token = BQDkwzsgHHp-wdrQh0WiGnnUQhzAXQZwhGfHIqSQcNgPdI0m8dNAfVslLj1FOsq53m41NnM7yk1HZPHor0TW0yB9PCsSnSarTV3PcjOAshaqlqycjOZrIuin7tX3SFlaaxOCm87-apezE1MFdk3PtBy1jTbbe43XR8_RtwBRO5Nwo7NfyHmglpz3874TsCVVVAMIFUycQ8jY_yLdA4k47462NfUE_Qo_57WmRvk Dec 06 16:50:03 volumio volumio[14232]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06: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]" Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06: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]" Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06: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]" Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=info msg="zeroconf server listening on port 42913" Dec 06 16:50:03 volumio volumio[14232]: info: Starting Shairport Sync Dec 06 16:50:03 volumio volumio[14232]: info: Starting Shairport Sync Dec 06 16:50:03 volumio volumio[14232]: info: Starting Shairport Sync Dec 06 16:50:03 volumio sudo[14516]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:03 volumio sudo[14516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=debug msg="obtained new client token: AADNZBLMCM4FwtUmdzXPoCGAjYNF4gMpcjbDdZ+BsgLy7FMBk6jJUE0UsP9+5nUWBrazbyPKqEm68d2Y9Y+/xFuE0u0fO0+J8Z8VS7pvPhwhrsK13+lTrXKDgSIkCo8ugthXbeuOinoNTGlKEdgKsP9wVqlcEPmB48/vbHl8mc2m1B5uCYd15evWF7zVqXPmhmXt29JSCxzTpmu7Bu402sa//lLxpArBXtNKFeuT4c8c4OpXTQ8vPYNOOQ==" Dec 06 16:50:03 volumio sudo[14520]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:03 volumio sudo[14520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:03 volumio sudo[14518]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:03 volumio sudo[14518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:03 volumio sudo[14514]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:50:03 volumio sudo[14514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:03 volumio sudo[14514]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:03 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:50:03 volumio volumio[14232]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:50:03 volumio volumio[14232]: info: Output device has changed, restarting MPD Dec 06 16:50:03 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:50:03 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:03 volumio systemd[1]: shairport-sync.service: Consumed 1.888s CPU time. Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:03 volumio volumio[14232]: info: Output device has changed, restarting Shairport Sync Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:03 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:03 volumio go-librespot[14503]: time="2025-12-06T16:50:03-06:00" level=debug msg="completed challenge" Dec 06 16:50:03 volumio sudo[14527]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:50:03 volumio sudo[14527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:04 volumio sudo[14528]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:50:04 volumio sudo[14527]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio sudo[14528]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:04 volumio go-librespot[14503]: time="2025-12-06T16:50:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:04 volumio volumio[14232]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:04 volumio sudo[14516]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:50:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:50:04 volumio sudo[14520]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:04 volumio volumio[14232]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 06 16:50:04 volumio sudo[14544]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 06 16:50:04 volumio sudo[14544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:04 volumio volumio[14232]: info: MPD Permissions set Dec 06 16:50:04 volumio volumio[14232]: info: Shairport-Sync Started Dec 06 16:50:04 volumio sudo[14544]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:04 volumio volumio[14232]: Error adding Membership: Error: addMembership EINVAL Dec 06 16:50:04 volumio volumio[14232]: info: Shairport-Sync Started Dec 06 16:50:04 volumio sudo[14518]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:50:04 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:50:04 volumio systemd[1]: mpd.service: Consumed 1.666s CPU time. Dec 06 16:50:04 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:50:04 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:50:04 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:50:04 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:50:04 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:50:04 volumio volumio[14232]: info: Shairport-Sync Started Dec 06 16:50:04 volumio volumio[14232]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:04 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:04 volumio volumio[14232]: info: Starting Shairport Sync Dec 06 16:50:04 volumio sudo[14557]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:50:04 volumio sudo[14557]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:04 volumio sudo[14557]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio sudo[14571]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:04 volumio sudo[14571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:04 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 06 16:50:04 volumio sudo[14575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 06 16:50:04 volumio sudo[14575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:04 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:50:04 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:50:04 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:04 volumio volumio[14232]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Dec 06 16:50:04 volumio volumio[14232]: info: Spotify Successfully logged in Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:04 volumio volumio[14232]: info: [1765061404596] CoreMusicLibrary::Adding element Spotify Dec 06 16:50:04 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:04 volumio volumio[14232]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:04 volumio volumio[14232]: Cannot find translation for source SoundCloud Dec 06 16:50:04 volumio volumio[14232]: Cannot find translation for source YouTube2 Dec 06 16:50:04 volumio volumio[14232]: Cannot find translation for source YouTube Music Dec 06 16:50:04 volumio volumio[14232]: Cannot find translation for source Podcast Dec 06 16:50:04 volumio volumio[14232]: Cannot find translation for source Volusonic Dec 06 16:50:04 volumio volumio[14232]: Cannot find translation for source Spotify Dec 06 16:50:04 volumio sudo[14547]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:50:04 volumio sudo[14547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:50:04 volumio sudo[14547]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:04 volumio sudo[14571]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:04 volumio systemd[1]: Reloading. Dec 06 16:50:04 volumio volumio[14232]: info: Shairport-Sync Started Dec 06 16:50:04 volumio volumio[14232]: info: [squeezelite_mc] Notification listener started Dec 06 16:50:04 volumio volumio[14232]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:50:05 volumio volumio[14232]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:50:05 volumio volumio[14232]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:50:05 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:05 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:05 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:05 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:06 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:06 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:06 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:50:06 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:50:06 volumio volumio[14232]: info: go-librespot daemon successfully initialized Dec 06 16:50:06 volumio sudo[14575]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:06 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:06 volumio sudo[14613]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:06 volumio sudo[14613]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:06 volumio sudo[14613]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:06 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 06 16:50:06 volumio sudo[14616]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 06 16:50:06 volumio sudo[14616]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:06 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:50:07 volumio volumio[14232]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 06 16:50:07 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:07 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 06 16:50:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:07 volumio go-librespot[14618]: go-librespot daemon starting... Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=debug msg="app state loaded" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:07 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 06 16:50:07 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:50:07 volumio sudo[14616]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06: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]" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06: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]" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06: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]" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=info msg="zeroconf server listening on port 42669" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=debug msg="obtained new client token: AAADKxSaOAvQZhQlm/qbl4Hdp1PuEeL0RugTaUAwI5QL7zCB/+Y04sS2fKyYYpFDHqDjFgGJnuXZl98VAkjtqrxbR+H9iO5AMAQZS1UAhe5/7pula5bIatTqal/DfHQe+rAMOE0AjLj2S10oTr4a6OjNGeVAZy0PQ60l34RTwm/PlUAB9Iv+6Gw0EcokqfYKaLpN4458Zr4JK+g63KtknuuIox8NnSQYSu99RzRJeG6ptNzNI001h90Klw==" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=debug msg="completed challenge" Dec 06 16:50:07 volumio go-librespot[14619]: time="2025-12-06T16:50:07-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:07 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:07 volumio sudo[14627]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:07 volumio sudo[14627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:07 volumio sudo[14627]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:07 volumio volumio[14232]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 06 16:50:07 volumio sudo[14631]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 06 16:50:07 volumio sudo[14631]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:07 volumio sudo[14631]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:07 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 06 16:50:08 volumio sudo[14634]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 06 16:50:08 volumio sudo[14634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:08 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:50:08 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:50:08 volumio sudo[14634]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:08 volumio mpd[14579]: 2025-12-06T16:50:08 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 06 16:50:08 volumio volumio[14232]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 06 16:50:08 volumio volumio[14232]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:50:08 volumio volumio[14232]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:50:08 volumio volumio[14232]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:50:08 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 06 16:50:08 volumio sudo[14446]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:08 volumio sudo[14528]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:08 volumio sudo[14436]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:08 volumio volumio[14232]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:50:08 volumio volumio[14232]: assert.ok(self.idling) Dec 06 16:50:08 volumio volumio[14232]: error: The expression evaluated to a falsy value: Dec 06 16:50:08 volumio volumio[14232]: assert.ok(self.idling) Dec 06 16:50:08 volumio volumio[14232]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:50:08 volumio volumio[14232]: assert.ok(self.idling) Dec 06 16:50:08 volumio volumio[14232]: error: The expression evaluated to a falsy value: Dec 06 16:50:08 volumio volumio[14232]: assert.ok(self.idling) Dec 06 16:50:08 volumio volumio[14232]: error: updateQueue error: null Dec 06 16:50:08 volumio volumio[14232]: info: MPD running with PID14579 Dec 06 16:50:08 volumio volumio[14232]: ,establishing connection Dec 06 16:50:08 volumio volumio[14232]: error: updateQueue error: null Dec 06 16:50:08 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:08 volumio sudo[14645]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:08 volumio sudo[14645]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:08 volumio sudo[14645]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:09 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:09 volumio sudo[14648]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:09 volumio sudo[14648]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:09 volumio sudo[14648]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:09 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:09 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:09 volumio volumio[14232]: info: Initializing connection to go-librespot Websocket Dec 06 16:50:09 volumio volumio[14232]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:50:09 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:09 volumio sudo[14665]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:09 volumio sudo[14665]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:10 volumio sudo[14665]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:10 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:10 volumio sudo[14668]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:10 volumio sudo[14668]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:10 volumio sudo[14668]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 06 16:50:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:10 volumio go-librespot[14670]: go-librespot daemon starting... Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=debug msg="app state loaded" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:11 volumio volumio[14232]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:11 volumio sudo[14678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:11 volumio sudo[14678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:11 volumio sudo[14678]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:11 volumio volumio[14232]: info: Completed starting Core Plugins Dec 06 16:50:11 volumio volumio[14232]: info: ------------------------------------------- Dec 06 16:50:11 volumio volumio[14232]: info: ----- MyVolumio plugins startup ---- Dec 06 16:50:11 volumio volumio[14232]: info: ------------------------------------------- Dec 06 16:50:11 volumio volumio[14232]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06: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]" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06: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]" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06: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]" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=info msg="zeroconf server listening on port 41077" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=debug msg="obtained new client token: AABp/9FWvAvBo0nImsrIxld2yly309kNfIjm3yg0q5+SoEFjgFvL3RtU8OrxvoZZ4OcNMrTNz+nQFJMKAJDp6zypSJdilRzCsSBxvH2OeS7TAuYhJFy9cdi0bBZyATa3yj+JQPHrGxxA/k8UY7YpUVGTSkC7FXdEBvpIAhbRp1OXWC4aHHfCbTJ6Rmjx7K+3jgg3rwIpdJQrDC9rJE2LLtGnWRQ6Kqm5JHG1qvBnVpZ9EXd09JQiyUr68w==" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=debug msg="completed challenge" Dec 06 16:50:11 volumio go-librespot[14671]: time="2025-12-06T16:50:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:11 volumio sudo[14682]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:50:11 volumio sudo[14682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:11 volumio sudo[14684]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:50:11 volumio sudo[14684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:11 volumio sudo[14686]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:50:11 volumio sudo[14686]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:11 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 06 16:50:11 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 06 16:50:11 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 06 16:50:11 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 06 16:50:11 volumio sudo[14686]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:11 volumio sudo[14684]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:11 volumio sudo[14682]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:11 volumio mpd_monitor.sh[14690]: MPD Monitor Service: Starting MPD Monitor Service Dec 06 16:50:11 volumio volumio[14232]: info: Successfully started MPD Monitor Dec 06 16:50:11 volumio volumio[14232]: info: Successfully started MPD Monitor Dec 06 16:50:11 volumio volumio[14232]: info: Successfully started MPD Monitor Dec 06 16:50:12 volumio volumio[14232]: info: Initializing connection to go-librespot Websocket Dec 06 16:50:12 volumio volumio[14232]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:50:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 06 16:50:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:14 volumio go-librespot[14694]: go-librespot daemon starting... Dec 06 16:50:14 volumio go-librespot[14695]: time="2025-12-06T16:50:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:14 volumio go-librespot[14695]: time="2025-12-06T16:50:14-06:00" level=debug msg="app state loaded" Dec 06 16:50:14 volumio go-librespot[14695]: time="2025-12-06T16:50:14-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:14 volumio go-librespot[14695]: time="2025-12-06T16:50:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06: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]" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06: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]" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06: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]" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06:00" level=info msg="zeroconf server listening on port 37795" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06:00" level=debug msg="obtained new client token: AADepnd02CjUa/8fiCAHdKRJqyXJJHsZDbBZcoVmOXNQy6fR4mxB9CbcG80k6dBDqzmLXcVveJjtEhiN7Grknv+EtBUIM7HaIDTyKB0goPQ47s0CKJMK878QTHAvpfp04Oc8XlbrBMosmBWUMZcPTDoiVj2dimQNpKMqRGS9pVRJ+ts0Mb7uyKI9QKaJCP+UNPVafNxiFvmRwqNWuxbuNOFKAlikTFk0shAF4/xqGOJcSOxflPjGHiY=" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06:00" level=debug msg="completed challenge" Dec 06 16:50:15 volumio go-librespot[14695]: time="2025-12-06T16:50:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:16 volumio volumio[14232]: info: Initializing connection to go-librespot Websocket Dec 06 16:50:16 volumio volumio[14232]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:50:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 06 16:50:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:18 volumio go-librespot[14702]: go-librespot daemon starting... Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=debug msg="app state loaded" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06: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]" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06: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]" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06: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]" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=info msg="zeroconf server listening on port 35505" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=debug msg="obtained new client token: AABqxgG0k9iBjcfTn2F6NFXNsRSO2ABPlza+iisqcVkkkJCY6BVwn+KlkJn2tEbUu2Twtrw57AcGVkliEyRDt6hQEiyWOrxO0EzPEV1NrAIEnRMkl+0Q2Cr75jncg/FAH9PiO6kbLKesnHOGL+iO8Dpuj0+aywxIph5L95aQK7ATT9hKNveWM9Z39Mt+HvAl6BaOcHkXN+sbGf9PD9fJt664KlNGNk2zobKEuKvSQN9HIuBh56sPfl0xYw==" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=debug msg="completed challenge" Dec 06 16:50:18 volumio go-librespot[14703]: time="2025-12-06T16:50:18-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 06 16:50:19 volumio volumio[14232]: info: Adding plugin bluetooth to MyMusic Plugins Dec 06 16:50:19 volumio volumio[14232]: info: Adding plugin multiroom to MyMusic Plugins Dec 06 16:50:19 volumio volumio[14232]: info: Adding plugin metavolumio to MyMusic Plugins Dec 06 16:50:19 volumio volumio[14232]: info: Adding plugin cd_controller to MyMusic Plugins Dec 06 16:50:19 volumio volumio[14232]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 06 16:50:19 volumio volumio[14232]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 06 16:50:19 volumio volumio[14232]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 06 16:50:19 volumio volumio[14232]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 06 16:50:20 volumio volumio[14232]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 06 16:50:20 volumio volumio[14232]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 06 16:50:20 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:20 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:20 volumio volumio[14232]: info: Starting MyVolumio Remote Streaming Endpoints Dec 06 16:50:20 volumio volumio[14232]: info: MyVolumio login type: Token Dec 06 16:50:20 volumio volumio[14232]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 06 16:50:20 volumio volumio[14232]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 06 16:50:21 volumio volumio[14232]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 06 16:50:21 volumio volumio[14232]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 06 16:50:21 volumio volumio[14232]: info: Streaming services startup Dec 06 16:50:21 volumio volumio[14232]: info: Starting Streaming Daemon Dec 06 16:50:21 volumio sudo[14725]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:50:21 volumio sudo[14725]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:21 volumio volumio[14232]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 06 16:50:21 volumio sudo[14725]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:21 volumio volumio[14232]: info: Initializing connection to go-librespot Websocket Dec 06 16:50:21 volumio volumio[14232]: error: Cannot start Volumio Streaming Daemon Dec 06 16:50:21 volumio volumio[14232]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:50:21 volumio volumio[14232]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:50:21 volumio volumio[14232]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:50:21 volumio volumio[14232]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 06 16:50:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 06 16:50:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:22 volumio go-librespot[14731]: go-librespot daemon starting... Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06:00" level=debug msg="app state loaded" Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:22 volumio volumio[14232]: info: MyVolumio token set successfully Dec 06 16:50:22 volumio volumio[14232]: info: MYVOLUMIO: Adding device Dec 06 16:50:22 volumio volumio[14232]: info: MYVOLUMIO: Evaluating Server Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06: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]" Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06: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]" Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06: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]" Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06:00" level=info msg="zeroconf server listening on port 41937" Dec 06 16:50:22 volumio volumio[14232]: info: MyVolumio status changed Dec 06 16:50:22 volumio volumio[14232]: info: Streaming services startup Dec 06 16:50:22 volumio volumio[14232]: info: Starting Streaming Daemon Dec 06 16:50:22 volumio volumio[14232]: info: Removing browser output: myVolumio user plan is not superstar Dec 06 16:50:22 volumio volumio[14232]: info: Removing audio output: Dec 06 16:50:22 volumio volumio[14232]: info: Stoppping Tunnel 1 Dec 06 16:50:22 volumio sudo[14760]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:50:22 volumio sudo[14760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06:00" level=debug msg="obtained new client token: AACoWovdcfEGz13fOy+c8puY+isgwG2JUGX7QCLvxeD3dFi5jlZA7h435LnzCMer6RfkCfMKVH3CYl4mM1/DWpT6oBnNUMICdRkyqlxdx94Kzjq54LgDD2tBPldwip6lKnqSM18wi3t+eqUksWWW5Y9ByfsjvxwQJs3YjCGVKPgrck0ft4OBh4wjciD4gg2wnqGCCY8pDw4QhW27ZX5rhrDV1Yd9sPqvA2FjbRtAhw2kknrDJP7W/5gR7A==" Dec 06 16:50:22 volumio sudo[14762]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 06 16:50:22 volumio sudo[14762]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:22 volumio sudo[14760]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:22 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. Dec 06 16:50:22 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. Dec 06 16:50:22 volumio go-librespot[14732]: time="2025-12-06T16:50:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:22 volumio volumio[14232]: error: Cannot start Volumio Streaming Daemon Dec 06 16:50:22 volumio volumio[14232]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:50:22 volumio volumio[14232]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:50:22 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. Dec 06 16:50:22 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. Dec 06 16:50:22 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. Dec 06 16:50:22 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. Dec 06 16:50:22 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. Dec 06 16:50:22 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. Dec 06 16:50:22 volumio sudo[14762]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:22 volumio volumio[14232]: info: Remote SSH Stopped Dec 06 16:50:22 volumio volumio[14232]: info: Setting Geolocation for MyVolumio to us1 Dec 06 16:50:22 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:22 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:22 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:23 volumio volumio[14232]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 06 16:50:23 volumio volumio[14232]: info: Updating MyVolumio device info Dec 06 16:50:23 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:23 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:23 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:23 volumio volumio[14232]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 06 16:50:24 volumio volumio[14232]: info: Initializing connection to go-librespot Websocket Dec 06 16:50:24 volumio go-librespot[14732]: time="2025-12-06T16:50:24-06:00" level=debug msg="new websocket client" Dec 06 16:50:24 volumio volumio[14232]: info: Connection to go-librespot Websocket established Dec 06 16:50:27 volumio volumio[14232]: info: MYVOLUMIO: Adding device Dec 06 16:50:27 volumio volumio[14232]: info: MYVOLUMIO: Evaluating Server Dec 06 16:50:27 volumio volumio[14232]: info: Setting Geolocation for MyVolumio to us4 Dec 06 16:50:27 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:27 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:27 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:27 volumio volumio[14232]: info: Getting Spotify volume Dec 06 16:50:27 volumio volumio[14232]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 06 16:50:27 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:27 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:27 volumio volumio[14232]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 06 16:50:27 volumio volumio[14232]: SPOTIFY: SPOTIFY VOLUME undefined Dec 06 16:50:27 volumio volumio[14232]: SPOTIFY: VOLUMIO VOLUME 86 Dec 06 16:50:27 volumio volumio[14232]: info: Aligning Spotify Volume to Volumio Volume Dec 06 16:50:27 volumio volumio[14232]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:27 volumio volumio[14232]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:27 volumio volumio[14232]: info: Setting Spotify Volume from Volumio: 86 Dec 06 16:50:28 volumio volumio[14232]: info: Updating MyVolumio device info Dec 06 16:50:28 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:28 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:28 volumio volumio[14232]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:28 volumio volumio[14232]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 06 16:50:28 volumio volumio[14232]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 06 16:50:29 volumio volumio[14232]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Dec 06 16:50:29 volumio volumio[14232]: info: Sending Spotify command with payload to local API: /player/volume Dec 06 16:50:30 volumio go-librespot[14732]: time="2025-12-06T16:50:30-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:30 volumio go-librespot[14732]: time="2025-12-06T16:50:30-06:00" level=debug msg="completed challenge" Dec 06 16:50:30 volumio go-librespot[14732]: time="2025-12-06T16:50:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:30 volumio volumio[14232]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Dec 06 16:50:30 volumio volumio[14232]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:50:30 volumio volumio[14232]: Error: socket hang up Dec 06 16:50:30 volumio volumio[14232]: at connResetException (node:internal/errors:720:14) Dec 06 16:50:30 volumio volumio[14232]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 06 16:50:30 volumio volumio[14232]: at Socket.emit (node:events:526:35) Dec 06 16:50:30 volumio volumio[14232]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 06 16:50:30 volumio volumio[14232]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 06 16:50:30 volumio volumio[14232]: code: 'ECONNRESET', Dec 06 16:50:30 volumio volumio[14232]: response: undefined Dec 06 16:50:30 volumio volumio[14232]: } Dec 06 16:50:30 volumio volumio[14232]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:50:31 volumio sudo[14812]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 16:49' Dec 06 16:50:31 volumio sudo[14812]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:31 volumio sudo[14812]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:31 volumio volumio-remote-updater[2353]: [2025-12-06 16:50:31] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 06 16:50:31 volumio volumio-remote-updater[2353]: [2025-12-06 16:50:31] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 06 16:50:31 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:31 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 06 16:50:31 volumio systemd[1]: volumio.service: Consumed 46.769s CPU time. Dec 06 16:50:31 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 16:50:31 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 16:50:31 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 21182. Dec 06 16:50:31 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 16:50:31 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 06 16:50:31 volumio systemd[1]: volumio.service: Consumed 46.769s CPU time. Dec 06 16:50:31 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 06 16:50:31 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 16:50:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 06 16:50:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:33 volumio go-librespot[14846]: go-librespot daemon starting... Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=debug msg="app state loaded" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:33 volumio volumio[14828]: info: ------------------------------------------- Dec 06 16:50:33 volumio volumio[14828]: info: ----- Volumio3 ---- Dec 06 16:50:33 volumio volumio[14828]: info: ------------------------------------------- Dec 06 16:50:33 volumio volumio[14828]: info: ----- System startup ---- Dec 06 16:50:33 volumio volumio[14828]: info: ------------------------------------------- Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06: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]" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06: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]" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06: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]" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=info msg="zeroconf server listening on port 39765" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=debug msg="obtained new client token: AACyzAySmn7cYg5f1Vj3meELcANKEmhM+T2SVNw+6PuR3oXCsjypJqUyio6JCvRQFF7Rrg/t8zFspzBKjoq31kBtX+/onst5fAkt68A4vtYz1n9u5ICnrw+OTJETXa1ALJNCxLK9Kc8GuTRRc+EWS8SA2d/bYCHwLtkzyN8cdm/OjqDJUAXIeyfb+dBIMjrb/HtaNy0SGDVzmvB/nV9HHNDJioR7TUZK/Q7DY7FqDliHO1N57gTvsh1lww==" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Dec 06 16:50:33 volumio go-librespot[14847]: time="2025-12-06T16:50:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Dec 06 16:50:34 volumio volumio[14828]: info: MYVOLUMIO Environment detected Dec 06 16:50:34 volumio volumio[14828]: info: Plugin folders cleanup Dec 06 16:50:34 volumio volumio[14828]: info: Scanning into folder /volumio/app/plugins/ Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category audio_interface Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category miscellanea Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category music_service Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category plugins.json Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category system_controller Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category user_interface Dec 06 16:50:34 volumio volumio[14828]: info: Scanning into folder /data/plugins/ Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category audio_interface Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category music_service Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category system_controller Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category system_hardware Dec 06 16:50:34 volumio volumio[14828]: info: Scanning category user_interface Dec 06 16:50:34 volumio volumio[14828]: info: Plugin folders cleanup completed Dec 06 16:50:34 volumio volumio[14828]: info: ------------------------------------------- Dec 06 16:50:34 volumio volumio[14828]: info: ----- Core plugins startup ---- Dec 06 16:50:34 volumio volumio[14828]: info: ------------------------------------------- Dec 06 16:50:34 volumio volumio[14828]: info: Loading plugins from folder /volumio/app/plugins/ Dec 06 16:50:34 volumio volumio[14828]: info: Adding plugin upnp to MyMusic Plugins Dec 06 16:50:34 volumio volumio[14828]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 06 16:50:34 volumio volumio[14828]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 06 16:50:34 volumio volumio[14828]: info: Loading plugins from folder /data/plugins/ Dec 06 16:50:34 volumio volumio[14828]: info: Loading plugin "system"... Dec 06 16:50:34 volumio volumio[14828]: info: Loading plugin "appearance"... Dec 06 16:50:35 volumio go-librespot[14847]: time="2025-12-06T16:50:35-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:35 volumio go-librespot[14847]: time="2025-12-06T16:50:35-06:00" level=debug msg="completed challenge" Dec 06 16:50:35 volumio go-librespot[14847]: time="2025-12-06T16:50:35-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:35 volumio volumio[14828]: info: Loading plugin "network"... Dec 06 16:50:35 volumio volumio[14828]: info: Refreshing Cached IP Addresses Dec 06 16:50:35 volumio sudo[14867]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 16:50:35 volumio sudo[14867]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:35 volumio sudo[14869]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 16:50:35 volumio sudo[14869]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:35 volumio volumio[14828]: info: Loading plugin "services"... Dec 06 16:50:35 volumio sudo[14869]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:35 volumio volumio[14828]: info: Loading plugin "alsa_controller"... Dec 06 16:50:35 volumio sudo[14867]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:35 volumio sudo[14881]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 06 16:50:35 volumio sudo[14881]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:35 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:50:35 volumio volumio[14828]: info: Loading plugin "wizard"... Dec 06 16:50:35 volumio volumio[14828]: info: Loading plugin "networkfs"... Dec 06 16:50:35 volumio volumio[14828]: info: Starting Udev Watcher for removable devices Dec 06 16:50:35 volumio volumio[14828]: info: Ignoring mount for partition: boot Dec 06 16:50:35 volumio volumio[14828]: info: Ignoring mount for partition: volumio Dec 06 16:50:35 volumio volumio[14828]: info: Ignoring mount for partition: volumio_data Dec 06 16:50:35 volumio volumio[14828]: info: Mounting Device Wikipedia Dec 06 16:50:36 volumio sudo[14906]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 06 16:50:36 volumio sudo[14906]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:36 volumio sudo[14906]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:36 volumio volumio[14828]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 06 16:50:36 volumio volumio[14828]: dmesg(1) may have more information after failed mount system call. Dec 06 16:50:36 volumio volumio[14828]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 06 16:50:36 volumio volumio[14828]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 06 16:50:36 volumio volumio[14828]: dmesg(1) may have more information after failed mount system call. Dec 06 16:50:36 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:50:36 volumio volumio[14828]: info: Loading plugin "volumio_command_line_client"... Dec 06 16:50:36 volumio volumio[14828]: info: Loading plugin "upnp"... Dec 06 16:50:36 volumio volumio[14828]: info: [1765061436060] Starting Upmpd Daemon Dec 06 16:50:36 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:50:36 volumio volumio[14828]: info: Loading plugin "my_music"... Dec 06 16:50:36 volumio volumio[14828]: info: Loading plugin "mpd"... Dec 06 16:50:36 volumio volumio[14828]: info: Loading plugin "upnp_browser"... Dec 06 16:50:36 volumio sudo[14881]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:36 volumio volumio-remote-updater[2353]: [2025-12-06 16:50:36] [connect] Successful connection Dec 06 16:50:37 volumio volumio[14828]: info: Loading plugin "alarm-clock"... Dec 06 16:50:38 volumio volumio[14828]: info: Loading plugin "airplay_emulation"... Dec 06 16:50:38 volumio volumio[14828]: info: Starting Shairport Sync Dec 06 16:50:38 volumio volumio[14828]: info: Loading plugin "last_100"... Dec 06 16:50:38 volumio volumio[14828]: info: Loading plugin "webradio"... Dec 06 16:50:38 volumio volumio[14828]: info: Loading plugin "i2s_dacs"... Dec 06 16:50:38 volumio volumio[14828]: info: I2S DAC not set, start Auto-detection Dec 06 16:50:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 06 16:50:38 volumio volumio[14828]: info: Loading plugin "volumiodiscovery"... Dec 06 16:50:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:38 volumio volumio[14828]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 16:50:38 volumio volumio[14828]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:50:38 volumio volumio[14828]: *** WARNING *** For more information see Dec 06 16:50:38 volumio volumio[14828]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 16:50:38 volumio volumio[14828]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:50:38 volumio volumio[14828]: *** WARNING *** For more information see Dec 06 16:50:38 volumio node[14828]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 16:50:38 volumio node[14828]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:50:38 volumio node[14828]: *** WARNING *** For more information see Dec 06 16:50:38 volumio node[14828]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 16:50:38 volumio node[14828]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 16:50:38 volumio node[14828]: *** WARNING *** For more information see Dec 06 16:50:38 volumio volumio[14828]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 06 16:50:38 volumio volumio[14828]: info: Discovery: Started advertising with name: Volumio Dec 06 16:50:38 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 16:50:38 volumio volumio[14828]: info: Loading plugin "bandcamp"... Dec 06 16:50:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:38 volumio go-librespot[14908]: go-librespot daemon starting... Dec 06 16:50:38 volumio go-librespot[14911]: time="2025-12-06T16:50:38-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:38 volumio go-librespot[14911]: time="2025-12-06T16:50:38-06:00" level=debug msg="app state loaded" Dec 06 16:50:38 volumio go-librespot[14911]: time="2025-12-06T16:50:38-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:38 volumio go-librespot[14911]: time="2025-12-06T16:50:38-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:39 volumio volumio[14828]: info: Plugin calmradio is not enabled Dec 06 16:50:39 volumio volumio[14828]: info: Loading plugin "soundcloud"... Dec 06 16:50:39 volumio volumio[14828]: info: Loading plugin "spop"... Dec 06 16:50:40 volumio volumio[14828]: info: Loading plugin "squeezelite_mc"... Dec 06 16:50:41 volumio volumio[14828]: info: Loading plugin "youtube2"... Dec 06 16:50:41 volumio go-librespot[14911]: time="2025-12-06T16:50:41-06: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]" Dec 06 16:50:41 volumio go-librespot[14911]: time="2025-12-06T16:50:41-06: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]" Dec 06 16:50:41 volumio go-librespot[14911]: time="2025-12-06T16:50:41-06: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]" Dec 06 16:50:41 volumio go-librespot[14911]: time="2025-12-06T16:50:41-06:00" level=info msg="zeroconf server listening on port 37589" Dec 06 16:50:42 volumio go-librespot[14911]: time="2025-12-06T16:50:42-06:00" level=debug msg="obtained new client token: AABhapY0AXF+9Pob7Sa+0ipnYqVvfxocuSwBLYCiGpP2M1pTRKwMRW9t23aIvGQA+w5OR6dTkwXs55TCP3u9lXi0MzyiHTZcALX8520HNkD3lJEVfbV/AU1k6PAD15xotMC6Y/zf9nZpVFMM+TGokUxq36VfKFKDf9CcDFzJUv8scVTMFqjQHoaz8pGLAueDWaz6DskuuSaXhx1yJ1QKQ1R+rsTuxKG6UcnbS7TPfTKtInAj7fn01ks=" Dec 06 16:50:42 volumio go-librespot[14911]: time="2025-12-06T16:50:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:42 volumio go-librespot[14911]: time="2025-12-06T16:50:42-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:42 volumio go-librespot[14911]: time="2025-12-06T16:50:42-06:00" level=debug msg="completed challenge" Dec 06 16:50:42 volumio go-librespot[14911]: time="2025-12-06T16:50:42-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:42 volumio volumio[14828]: info: Loading plugin "ytcr"... Dec 06 16:50:43 volumio volumio[14828]: info: Loading plugin "ytmusic"... Dec 06 16:50:44 volumio volumio[14828]: info: Plugin now_playing is not enabled Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "outputs"... Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "albumart"... Dec 06 16:50:44 volumio volumio[14828]: info: Plugin example_plugin is not enabled Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "inputs"... Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "updater_comm"... Dec 06 16:50:44 volumio volumio[14828]: info: Plugin mpdemulation is not enabled Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "rest_api"... Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "websocket"... Dec 06 16:50:44 volumio volumio[14828]: info: Starting Socket.io Server version 1.7.4 Dec 06 16:50:44 volumio volumio[14828]: info: Plugin fusiondsp is not enabled Dec 06 16:50:44 volumio volumio[14828]: info: Plugin mpdoutput is not enabled Dec 06 16:50:44 volumio volumio[14828]: info: Plugin RoonBridge is not enabled Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "podcast"... Dec 06 16:50:44 volumio volumio[14828]: info: ControllerPodcast::constructor Dec 06 16:50:44 volumio volumio[14828]: info: Loading plugin "volusonic"... Dec 06 16:50:44 volumio volumio[14919]: Forking 3 albumart workers Dec 06 16:50:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 06 16:50:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:45 volumio go-librespot[14960]: go-librespot daemon starting... Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06:00" level=debug msg="app state loaded" Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06: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]" Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06: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]" Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06: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]" Dec 06 16:50:45 volumio go-librespot[14961]: time="2025-12-06T16:50:45-06:00" level=info msg="zeroconf server listening on port 35141" Dec 06 16:50:46 volumio go-librespot[14961]: time="2025-12-06T16:50:46-06:00" level=debug msg="obtained new client token: AAAixOgIlvQRkn2JYZ6kqlH4K0U3tAxM232SCg6xsAznxEVeMaRpYFfHhQHCfOh/FP5cNQ55ssb/ZIvloeCUPteYpf8WbdE6iOgV3jmDVSF2phq3FhKclYGJ20J7FWIBzqLRIJ590VQ0hSjHkW/IW4Tv40r0LPaawekjnwSzrZlbNsZdeMJN5iyTg7cObujLwRjvlzzpaCqv38sghaEMKx+S1EN+zM4HuHBGOxcpGBjhIAsCqtwFlV0=" Dec 06 16:50:46 volumio go-librespot[14961]: time="2025-12-06T16:50:46-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:46 volumio volumio[14828]: info: Applying required configuration parameters for plugin volusonic Dec 06 16:50:46 volumio volumio[14828]: info: Loading plugin "backup_restore"... Dec 06 16:50:46 volumio go-librespot[14961]: time="2025-12-06T16:50:46-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:46 volumio go-librespot[14961]: time="2025-12-06T16:50:46-06:00" level=debug msg="completed challenge" Dec 06 16:50:46 volumio go-librespot[14961]: time="2025-12-06T16:50:46-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:46 volumio volumio[14929]: Starting albumart workers Dec 06 16:50:46 volumio volumio[14931]: Starting albumart workers Dec 06 16:50:46 volumio volumio[14930]: Starting albumart workers Dec 06 16:50:46 volumio volumio[14828]: info: Applying required configuration parameters for plugin backup_restore Dec 06 16:50:46 volumio volumio[14828]: info: Plugin rpi_eeprom_config is not enabled Dec 06 16:50:46 volumio volumio[14828]: info: Plugin rpi_eeprom_updater is not enabled Dec 06 16:50:46 volumio volumio[14828]: info: Loading plugin "scheduledrestart"... Dec 06 16:50:46 volumio volumio[14828]: info: Applying required configuration parameters for plugin scheduledrestart Dec 06 16:50:46 volumio volumio[14828]: info: Plugin Bluetoothremote is not enabled Dec 06 16:50:46 volumio volumio[14828]: info: Plugin music_services_shield is not enabled Dec 06 16:50:46 volumio volumio[14828]: info: Loading plugin "Systeminfo"... Dec 06 16:50:47 volumio volumio[14828]: info: Plugin peppymeterbasic is not enabled Dec 06 16:50:47 volumio volumio[14828]: info: Loading plugin "peppyspectrum"... Dec 06 16:50:47 volumio volumio[14828]: info: Loading i18n strings for locale en Dec 06 16:50:47 volumio volumio[14828]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:50:47 volumio volumio[14828]: Updating browse sources language Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::initPlayerControls Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:47 volumio volumio[14828]: Express server listening on port 3000 Dec 06 16:50:47 volumio volumio[14828]: [Metrics] WebUI: 14s 617.18ms Dec 06 16:50:47 volumio volumio[14828]: info: CoreStateMachine::resetVolumioState Dec 06 16:50:47 volumio volumio[14828]: info: CoreStateMachine::getcurrentVolume Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:50:47 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:47 volumio sudo[15005]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 16:50:47 volumio sudo[15005]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:47 volumio sudo[15005]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:47 volumio sudo[15007]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 16:50:47 volumio sudo[15007]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:47 volumio sudo[15007]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:47 volumio volumio[14828]: info: Volumio Network Manager: Network status updated: 1 Dec 06 16:50:48 volumio volumio[14828]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:50:48 volumio volumio[14828]: info: CoreStateMachine::pushState Dec 06 16:50:48 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:48 volumio volumio[14828]: info: CoreStateMachine::updateTrackBlock Dec 06 16:50:48 volumio volumio[14828]: info: CorePlayQueue::getTrackBlock Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:50:48 volumio volumio[14828]: info: Reloading queue from file Dec 06 16:50:48 volumio volumio[14828]: info: CoreStateMachine::setRepeat null single undefined Dec 06 16:50:48 volumio volumio[14828]: info: CoreStateMachine::pushState Dec 06 16:50:48 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:48 volumio volumio[14828]: info: CoreStateMachine::setRandom null Dec 06 16:50:48 volumio volumio[14828]: info: CoreStateMachine::pushState Dec 06 16:50:48 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:48 volumio volumio[14828]: info: Setting Device type: Raspberry PI Dec 06 16:50:48 volumio volumio[14828]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:50:48 volumio volumio[14828]: info: CoreStateMachine::pushState Dec 06 16:50:48 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:48 volumio volumio[14828]: info: Completed loading Core Plugins Dec 06 16:50:48 volumio volumio[14828]: info: Preparing to generate the ALSA configuration file Dec 06 16:50:48 volumio sudo[15020]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 06 16:50:48 volumio sudo[15020]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:48 volumio volumio[14828]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:50:48 volumio volumio[14828]: info: Discovery: Found device Volumio Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:48 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:48 volumio volumio[14828]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 06 16:50:48 volumio volumio[14828]: info: Discovery: Found device Volumio Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:48 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:48 volumio sudo[15020]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:48 volumio volumio[14828]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:50:48 volumio volumio[14828]: info: Reading ALSA contributions from plugins. Dec 06 16:50:48 volumio volumio[14828]: info: Upmpdcli Daemon Started Dec 06 16:50:48 volumio volumio[14828]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:50:48 volumio volumio[14828]: info: Output device has changed, restarting MPD Dec 06 16:50:48 volumio volumio[14828]: info: Output device has changed, restarting Shairport Sync Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:48 volumio sudo[15023]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:50:48 volumio sudo[15023]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:48 volumio sudo[15023]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:48 volumio sudo[15025]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:50:48 volumio sudo[15025]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:48 volumio volumio[14828]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:48 volumio volumio[14828]: info: ___________ START PLUGINS ___________ Dec 06 16:50:48 volumio volumio[14828]: info: ControllerMpd::onStart: Initializing MPD Dec 06 16:50:48 volumio volumio[14828]: info: Creating MPD Configuration file Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448331] CoreMusicLibrary::Adding element Media Servers Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio sudo[15033]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:50:48 volumio sudo[15033]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:48 volumio sudo[15033]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:48 volumio sudo[15035]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:50:48 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 06 16:50:48 volumio sudo[15035]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:48 volumio volumio[14828]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:48 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:50:48 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:50:48 volumio systemd[1]: mpd.service: Consumed 4.538s CPU time. Dec 06 16:50:48 volumio volumio[14828]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:48 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448454] CoreMusicLibrary::Adding element Last_100 Dec 06 16:50:48 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:50:48 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448462] CoreMusicLibrary::Adding element Webradio Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:50:48 volumio volumio[14828]: info: Initializing BBC Radios Dec 06 16:50:48 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:48 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448546] CoreMusicLibrary::Adding element Bandcamp Discover Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448559] CoreMusicLibrary::Adding element SoundCloud Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:48 volumio volumio[14828]: info: Creating Spotify config file Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:48 volumio sudo[15060]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:50:48 volumio sudo[15060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:50:48 volumio sudo[15060]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:48 volumio volumio[14828]: info: [squeezelite_mc] Starting proxy server... Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448942] CoreMusicLibrary::Adding element YouTube2 Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source YouTube2 Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448962] CoreMusicLibrary::Adding element YouTube Music Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source YouTube2 Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source YouTube Music Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:48 volumio volumio[14828]: info: [1765061448977] CoreMusicLibrary::Adding element Podcast Dec 06 16:50:48 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source YouTube2 Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source YouTube Music Dec 06 16:50:48 volumio volumio[14828]: Cannot find translation for source Podcast Dec 06 16:50:49 volumio volumio[14828]: info: Loading i18n strings for locale en Dec 06 16:50:49 volumio volumio[14828]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 06 16:50:49 volumio volumio[14828]: Updating browse sources language Dec 06 16:50:49 volumio volumio-remote-updater[2353]: [2025-12-06 16:50:49] [connect] Successful connection Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source YouTube2 Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source YouTube Music Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source Podcast Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source YouTube2 Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source YouTube Music Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source Podcast Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:49 volumio volumio[14828]: info: [1765061449031] CoreMusicLibrary::Adding element Volusonic Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source YouTube2 Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source YouTube Music Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source Podcast Dec 06 16:50:49 volumio volumio[14828]: Cannot find translation for source Volusonic Dec 06 16:50:49 volumio volumio[14828]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 06 16:50:49 volumio volumio[14828]: info: Volumio Calling Home Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Proxy server started on port 40903 Dec 06 16:50:49 volumio volumio[14828]: info: Preparing to generate the ALSA configuration file Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 16:50:49 volumio volumio[14828]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 06 16:50:49 volumio volumio[14828]: info: Reading ALSA contributions from plugins. Dec 06 16:50:49 volumio volumio[14828]: info: MPD Permissions set Dec 06 16:50:49 volumio volumio[14828]: info: MPD Permissions set Dec 06 16:50:49 volumio volumio-remote-updater[2353]: [2025-12-06 16:50:49] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765061449 101 Dec 06 16:50:49 volumio volumio[14828]: 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 Dec 06 16:50:49 volumio volumio[14828]: info: Spotify config file written Dec 06 16:50:49 volumio sudo[15070]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 06 16:50:49 volumio sudo[15070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 06 16:50:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:49 volumio volumio[14828]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 06 16:50:49 volumio volumio[14828]: info: VolumeController:: Volume=86 Mute =false Dec 06 16:50:49 volumio volumio[14828]: info: CoreStateMachine::pushState Dec 06 16:50:49 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::volumioPushState Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Server discovery started Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Player finder started Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 06 16:50:49 volumio go-librespot[15072]: go-librespot daemon starting... Dec 06 16:50:49 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 06 16:50:49 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 06 16:50:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:49 volumio go-librespot[15079]: go-librespot daemon starting... Dec 06 16:50:49 volumio sudo[15070]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06:00" level=debug msg="app state loaded" Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:49 volumio volumio[14828]: info: No need to fix Spotify hosts Dec 06 16:50:49 volumio volumio[14828]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 06 16:50:49 volumio volumio[14828]: info: Volumio called home Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"} Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06: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]" Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06: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]" Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06: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]" Dec 06 16:50:49 volumio go-librespot[15082]: time="2025-12-06T16:50:49-06:00" level=info msg="zeroconf server listening on port 34745" Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 06 16:50:49 volumio volumio[14828]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:50:49 volumio volumio[14828]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:50:49 volumio volumio[14828]: SPOTIFY: BQBd-ofrhhYALyrLVEAr_Mh-m5ggJmgzERi3ZU1geV8XMBsWte-Jb5Vys1WIT1MossoqHWWQoRq3UPPalKPx-YYv_2tyCL2Pl3QYSPf9efdKfkwsVgBYYN8nVgJU-SRCuk_SQ6N7_mM__yC3UTEV_D85y0Y84zDGAHO5P6I0MoXjNlsCwO77UC_O-TMyS1v4IIIVOzdB3L8D057c9OAK93f5eWpQDdf4VSAPoOc Dec 06 16:50:49 volumio volumio[14828]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 06 16:50:49 volumio volumio[14828]: info: New Spotify access token = BQBd-ofrhhYALyrLVEAr_Mh-m5ggJmgzERi3ZU1geV8XMBsWte-Jb5Vys1WIT1MossoqHWWQoRq3UPPalKPx-YYv_2tyCL2Pl3QYSPf9efdKfkwsVgBYYN8nVgJU-SRCuk_SQ6N7_mM__yC3UTEV_D85y0Y84zDGAHO5P6I0MoXjNlsCwO77UC_O-TMyS1v4IIIVOzdB3L8D057c9OAK93f5eWpQDdf4VSAPoOc Dec 06 16:50:49 volumio volumio[14828]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 06 16:50:49 volumio volumio[14828]: info: Starting Shairport Sync Dec 06 16:50:49 volumio volumio[14828]: info: Starting Shairport Sync Dec 06 16:50:50 volumio go-librespot[15082]: time="2025-12-06T16:50:50-06:00" level=debug msg="obtained new client token: AAB7mmTXS6LmTnbrKLYFuI2GvZptQq5hEI7+T+Xid1+ssaxmd9YSqMASjXgPsWD4yME6TAChs7gI87l26KS4Ci2O8Pcjh70YJFbk1sfDNvv1iRwkiLn0/IC6C5w22XFHeESkTGnlnljugWTYkunDilRHxqF2EkdnTuR8mXiA9/npKhCL0hrgfqNCf+OXsg7VohYh7WQxr5Wo1nbNk39c0Lm80eA33HzOilkEa4SHLg71cCjuNIK1VEPDPg==" Dec 06 16:50:50 volumio volumio[14828]: info: Starting Shairport Sync Dec 06 16:50:50 volumio sudo[15101]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:50 volumio sudo[15101]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio sudo[15103]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:50 volumio sudo[15103]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio go-librespot[15082]: time="2025-12-06T16:50:50-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:50 volumio sudo[15099]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Dec 06 16:50:50 volumio sudo[15099]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio sudo[15106]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:50 volumio sudo[15106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio sudo[15099]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:50:50 volumio go-librespot[15082]: time="2025-12-06T16:50:50-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:50 volumio go-librespot[15082]: time="2025-12-06T16:50:50-06:00" level=debug msg="completed challenge" Dec 06 16:50:50 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:50:50 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:50 volumio systemd[1]: shairport-sync.service: Consumed 1.733s CPU time. Dec 06 16:50:50 volumio volumio[14828]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 06 16:50:50 volumio volumio[14828]: info: Asound.conf file unchanged, so no further update is needed Dec 06 16:50:50 volumio go-librespot[15082]: time="2025-12-06T16:50:50-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:50 volumio volumio[14828]: info: Output device has changed, restarting MPD Dec 06 16:50:50 volumio sudo[15113]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 06 16:50:50 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:50 volumio volumio[14828]: info: Output device has changed, restarting Shairport Sync Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:50 volumio sudo[15113]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio sudo[15101]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:50 volumio sudo[15115]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 16:50:50 volumio sudo[15115]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio sudo[15115]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio sudo[15103]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio sudo[15117]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 16:50:50 volumio sudo[15117]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:50:50 volumio sudo[15113]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:50:50 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:50 volumio volumio[14828]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 16:50:50 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:50 volumio sudo[15106]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 06 16:50:50 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 16:50:50 volumio systemd[1]: mpd.service: Consumed 1.809s CPU time. Dec 06 16:50:50 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 06 16:50:50 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 16:50:50 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 16:50:50 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 16:50:50 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 16:50:50 volumio volumio[14828]: info: MPD Permissions set Dec 06 16:50:50 volumio volumio[14828]: info: Shairport-Sync Started Dec 06 16:50:50 volumio volumio[14828]: Error adding Membership: Error: addMembership EINVAL Dec 06 16:50:50 volumio volumio[14828]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:50:50 volumio volumio[14828]: info: Shairport-Sync Started Dec 06 16:50:50 volumio volumio[14828]: info: Shairport-Sync Started Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:50 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:50 volumio sudo[15160]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Dec 06 16:50:50 volumio sudo[15160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio sudo[15160]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio sudo[15155]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 16:50:50 volumio sudo[15155]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 16:50:50 volumio volumio[14828]: info: Starting Shairport Sync Dec 06 16:50:50 volumio sudo[15155]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:50 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 06 16:50:50 volumio sudo[15169]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 16:50:50 volumio sudo[15169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio volumio[14828]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"} Dec 06 16:50:50 volumio volumio[14828]: info: Spotify Successfully logged in Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 16:50:50 volumio sudo[15172]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 06 16:50:50 volumio sudo[15172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:50 volumio volumio[14828]: info: [1765061450876] CoreMusicLibrary::Adding element Spotify Dec 06 16:50:50 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 16:50:50 volumio volumio[14828]: Cannot find translation for source Bandcamp Discover Dec 06 16:50:50 volumio volumio[14828]: Cannot find translation for source SoundCloud Dec 06 16:50:50 volumio volumio[14828]: Cannot find translation for source YouTube2 Dec 06 16:50:50 volumio volumio[14828]: Cannot find translation for source YouTube Music Dec 06 16:50:50 volumio volumio[14828]: Cannot find translation for source Podcast Dec 06 16:50:50 volumio volumio[14828]: Cannot find translation for source Volusonic Dec 06 16:50:50 volumio volumio[14828]: Cannot find translation for source Spotify Dec 06 16:50:50 volumio systemd[1]: Reloading. Dec 06 16:50:51 volumio volumio[14828]: info: [squeezelite_mc] Notification listener started Dec 06 16:50:51 volumio volumio[14828]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:50:51 volumio volumio[14828]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:50:51 volumio volumio[14828]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:50:51 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:51 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:51 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:50:51 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 16:50:52 volumio volumio[14828]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:52 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:52 volumio volumio[14828]: info: go-librespot daemon successfully initialized Dec 06 16:50:52 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:50:52 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 06 16:50:53 volumio sudo[15172]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:53 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:53 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 16:50:53 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 16:50:53 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:53 volumio systemd[1]: shairport-sync.service: Consumed 1.530s CPU time. Dec 06 16:50:53 volumio sudo[15196]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:53 volumio sudo[15196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:53 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 16:50:53 volumio sudo[15169]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:53 volumio volumio[14828]: info: Shairport-Sync Started Dec 06 16:50:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 06 16:50:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:53 volumio go-librespot[15211]: go-librespot daemon starting... Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=debug msg="app state loaded" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:53 volumio sudo[15196]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:53 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 06 16:50:53 volumio sudo[15220]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 06 16:50:53 volumio sudo[15220]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:53 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:50:53 volumio volumio[14828]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 06 16:50:53 volumio volumio[14828]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:53 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06: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]" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06: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]" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06: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]" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=info msg="zeroconf server listening on port 45783" Dec 06 16:50:53 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 06 16:50:53 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=debug msg="obtained new client token: AAA/n92O3Sl2/UBxx63288Rr11IWHY/HSN0zFeVrHYWCF1n6JGX1DjpgM9Er+bJa5SAuvK9iOR2S5Kt0b+48KQKhrGXR6JsOZrTDEds9Gsylq3tCyCNtqnbxwl5TLwZjtJvRGJTxZQ+Zh6zYylQccDv6St3LyK2OWu2gzuQLiRZQ4taAy6/NBAktrd6ta1xVqCzXZZG3PLWWLg3wQ5H4F8aiPOeY22yhbyKlVznCvEq0BMc0bEDSxMfBEQ==" Dec 06 16:50:53 volumio sudo[15220]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=debug msg="completed challenge" Dec 06 16:50:53 volumio go-librespot[15212]: time="2025-12-06T16:50:53-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:54 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:54 volumio sudo[15224]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:54 volumio sudo[15224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:54 volumio sudo[15224]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:54 volumio volumio[14828]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 06 16:50:54 volumio sudo[15228]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 06 16:50:54 volumio sudo[15228]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:54 volumio sudo[15228]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:54 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 06 16:50:54 volumio sudo[15231]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 06 16:50:54 volumio sudo[15231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:54 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 06 16:50:54 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 06 16:50:54 volumio sudo[15231]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:54 volumio volumio[14828]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 06 16:50:54 volumio volumio[14828]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 06 16:50:54 volumio mpd[15170]: 2025-12-06T16:50:54 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 06 16:50:54 volumio volumio[14828]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}] Dec 06 16:50:54 volumio volumio[14828]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}} Dec 06 16:50:54 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 06 16:50:54 volumio sudo[15025]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:54 volumio sudo[15035]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:54 volumio sudo[15117]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:55 volumio volumio[14828]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:50:55 volumio volumio[14828]: assert.ok(self.idling) Dec 06 16:50:55 volumio volumio[14828]: error: The expression evaluated to a falsy value: Dec 06 16:50:55 volumio volumio[14828]: assert.ok(self.idling) Dec 06 16:50:55 volumio volumio[14828]: error: MPD error: The expression evaluated to a falsy value: Dec 06 16:50:55 volumio volumio[14828]: assert.ok(self.idling) Dec 06 16:50:55 volumio volumio[14828]: error: The expression evaluated to a falsy value: Dec 06 16:50:55 volumio volumio[14828]: assert.ok(self.idling) Dec 06 16:50:55 volumio volumio[14828]: info: MPD running with PID15170 Dec 06 16:50:55 volumio volumio[14828]: ,establishing connection Dec 06 16:50:55 volumio volumio[14828]: error: updateQueue error: null Dec 06 16:50:55 volumio volumio[14828]: error: updateQueue error: null Dec 06 16:50:55 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:55 volumio sudo[15243]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:55 volumio sudo[15243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:55 volumio sudo[15243]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:55 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:55 volumio sudo[15246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:55 volumio sudo[15246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:55 volumio sudo[15246]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:55 volumio volumio[14828]: info: CoreCommandRouter::volumioGetState Dec 06 16:50:55 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:50:55 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:50:55 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:50:56 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:56 volumio sudo[15263]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:56 volumio sudo[15263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:56 volumio sudo[15263]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:56 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:56 volumio sudo[15266]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:56 volumio sudo[15266]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 06 16:50:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:50:57 volumio go-librespot[15268]: go-librespot daemon starting... Dec 06 16:50:57 volumio sudo[15266]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=debug msg="app state loaded" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=debug msg="stored credentials not found" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06: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]" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06: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]" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06: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]" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=info msg="zeroconf server listening on port 35077" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=debug msg="obtained new client token: AAC7o6/IwJ5StXNKzH7eZY/s3kql3WBU8bAC3NKxVfl58W5J1Rc+UX2MergtL+JxBnTiZBa2KGS6b+RMW04jRyv582nluuFRk69bsEulGyZxl5YCdfIqgThyiJpWy4E5XiHk5ybzP3pijLR5AKGwBG6PUFIhjomRUokj/FKsxVh5FQUvauhS70QWQ7mYrUTlw1fcIcvCSnPqyHW3/e1q+iCFVee2GP5obfmCOXcPwso54REz+K5MnGbvKw==" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=debug msg="completed keyexchange" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=debug msg="completed challenge" Dec 06 16:50:57 volumio go-librespot[15269]: time="2025-12-06T16:50:57-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:50:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:50:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:50:57 volumio volumio[14828]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 06 16:50:57 volumio sudo[15277]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 06 16:50:57 volumio sudo[15277]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:57 volumio sudo[15277]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:57 volumio volumio[14828]: info: Completed starting Core Plugins Dec 06 16:50:57 volumio volumio[14828]: info: ------------------------------------------- Dec 06 16:50:57 volumio volumio[14828]: info: ----- MyVolumio plugins startup ---- Dec 06 16:50:57 volumio volumio[14828]: info: ------------------------------------------- Dec 06 16:50:57 volumio volumio[14828]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 06 16:50:58 volumio sudo[15280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:50:58 volumio sudo[15280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:58 volumio sudo[15282]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:50:58 volumio sudo[15282]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:58 volumio sudo[15285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 16:50:58 volumio sudo[15285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:50:58 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 06 16:50:58 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 06 16:50:58 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 06 16:50:58 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 06 16:50:58 volumio sudo[15282]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:58 volumio sudo[15285]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:58 volumio mpd_monitor.sh[15289]: MPD Monitor Service: Starting MPD Monitor Service Dec 06 16:50:58 volumio sudo[15280]: pam_unix(sudo:session): session closed for user root Dec 06 16:50:58 volumio volumio[14828]: info: Successfully started MPD Monitor Dec 06 16:50:58 volumio volumio[14828]: info: Successfully started MPD Monitor Dec 06 16:50:58 volumio volumio[14828]: info: Successfully started MPD Monitor Dec 06 16:50:58 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:50:58 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 06 16:51:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:00 volumio go-librespot[15293]: go-librespot daemon starting... Dec 06 16:51:00 volumio go-librespot[15294]: time="2025-12-06T16:51:00-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:00 volumio go-librespot[15294]: time="2025-12-06T16:51:00-06:00" level=debug msg="app state loaded" Dec 06 16:51:00 volumio go-librespot[15294]: time="2025-12-06T16:51:00-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:00 volumio go-librespot[15294]: time="2025-12-06T16:51:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06: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]" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06: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]" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06: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]" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06:00" level=info msg="zeroconf server listening on port 46119" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06:00" level=debug msg="obtained new client token: AABnoBA9ZGaTIb209ciRppdg+OWy9qVxUraomDzGyoO1Sa+YkNoF7K6gqxMATTFXJGJmhuMuShaLBcFHdReOZoSS1R2HJ0TB8IiyZyg3Aa1ptY2YwJHkUDFy1u5KzI/nkARfGHcu3+2HY6sd6qp9ttA6+p07wdBmnBocWuM3SSHBErtRBmlq+BRaW7Fek6GUPBmdp1uEuo02mjwAjyJKf/P5ArUrHt83SyLpcKZwzXjGNF7vnVReRK8=" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06:00" level=debug msg="completed challenge" Dec 06 16:51:01 volumio go-librespot[15294]: time="2025-12-06T16:51:01-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:02 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:02 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 06 16:51:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:04 volumio go-librespot[15301]: go-librespot daemon starting... Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=debug msg="app state loaded" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06: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]" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06: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]" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06: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]" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=info msg="zeroconf server listening on port 37567" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=debug msg="obtained new client token: AAAIPz3K7XyLodSpOuEsf1FjmX1BFUEqHlzsr8CYPP+/NBxoJ1MOVYznBG+6tjxazDLMqAWhSusqT28PvFSuu+3yQUqXxLdBQkge1yfACCmN0A+Co4+v6LbzzEDm/ee9CNc+EgauaIo8Lgf52DaYP7DKECQxys0op13/13OuyUlaELWY5mgRQR9wybA6X70/4nwXFnIoKX7ILkC8CLvh6eYgzp9sOtKNBc/tBvgNDmPn9UbokQAjd4xyag==" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=debug msg="completed challenge" Dec 06 16:51:04 volumio go-librespot[15302]: time="2025-12-06T16:51:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:05 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:05 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 06 16:51:05 volumio volumio[14828]: info: Adding plugin bluetooth to MyMusic Plugins Dec 06 16:51:05 volumio volumio[14828]: info: Adding plugin multiroom to MyMusic Plugins Dec 06 16:51:05 volumio volumio[14828]: info: Adding plugin metavolumio to MyMusic Plugins Dec 06 16:51:05 volumio volumio[14828]: info: Adding plugin cd_controller to MyMusic Plugins Dec 06 16:51:05 volumio volumio[14828]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 06 16:51:05 volumio volumio[14828]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 06 16:51:05 volumio volumio[14828]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 06 16:51:05 volumio volumio[14828]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 06 16:51:06 volumio volumio[14828]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 06 16:51:06 volumio volumio[14828]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 06 16:51:06 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:06 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:06 volumio volumio[14828]: info: Starting MyVolumio Remote Streaming Endpoints Dec 06 16:51:06 volumio volumio[14828]: info: MyVolumio login type: Token Dec 06 16:51:06 volumio volumio[14828]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 06 16:51:06 volumio volumio[14828]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 06 16:51:07 volumio volumio[14828]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 06 16:51:07 volumio volumio[14828]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 06 16:51:07 volumio volumio[14828]: info: Streaming services startup Dec 06 16:51:07 volumio volumio[14828]: info: Starting Streaming Daemon Dec 06 16:51:07 volumio sudo[15325]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:51:07 volumio sudo[15325]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:51:07 volumio volumio[14828]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 06 16:51:07 volumio sudo[15325]: pam_unix(sudo:session): session closed for user root Dec 06 16:51:07 volumio volumio[14828]: error: Cannot start Volumio Streaming Daemon Dec 06 16:51:07 volumio volumio[14828]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:51:07 volumio volumio[14828]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:51:08 volumio volumio[14828]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 06 16:51:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 06 16:51:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:08 volumio go-librespot[15331]: go-librespot daemon starting... Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=debug msg="app state loaded" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06: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]" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06: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]" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06: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]" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=info msg="zeroconf server listening on port 39827" Dec 06 16:51:08 volumio volumio[14828]: info: MyVolumio token set successfully Dec 06 16:51:08 volumio volumio[14828]: info: MYVOLUMIO: Adding device Dec 06 16:51:08 volumio volumio[14828]: info: MYVOLUMIO: Evaluating Server Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=debug msg="obtained new client token: AACI/rXdIqQpv4CRh8Hzw1cs+EPU8vmrbOOaj2cPsl8d7h6N4E+t5OKgL6KUOEm2g727qnO97dEAzlYlB2AKomHUW1h6+5lCTeEtxPuYP3II4gEaLEfvSyC7WUQsR3m/BG0r4u23Kmp3dDabWnEsAoLQwx4IXQeliIFH71aESFDptow4vlLvpEeBB+PjNhPJGwmArU64ZHUidewa084YVXXockIST2nGoRd7cBwHQr60wOSY4SIuezGjVQ==" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=debug msg="completed challenge" Dec 06 16:51:08 volumio volumio[14828]: info: MyVolumio status changed Dec 06 16:51:08 volumio volumio[14828]: info: Streaming services startup Dec 06 16:51:08 volumio volumio[14828]: info: Starting Streaming Daemon Dec 06 16:51:08 volumio go-librespot[15332]: time="2025-12-06T16:51:08-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:08 volumio volumio[14828]: info: Removing browser output: myVolumio user plan is not superstar Dec 06 16:51:08 volumio volumio[14828]: info: Removing audio output: Dec 06 16:51:08 volumio volumio[14828]: info: Stoppping Tunnel 1 Dec 06 16:51:08 volumio sudo[15360]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 16:51:08 volumio sudo[15360]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:51:08 volumio sudo[15362]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 06 16:51:08 volumio sudo[15362]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:51:08 volumio sudo[15360]: pam_unix(sudo:session): session closed for user root Dec 06 16:51:08 volumio volumio[14828]: error: Cannot start Volumio Streaming Daemon Dec 06 16:51:08 volumio volumio[14828]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 16:51:08 volumio volumio[14828]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 16:51:08 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:08 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:08 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. Dec 06 16:51:08 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. Dec 06 16:51:08 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. Dec 06 16:51:08 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. Dec 06 16:51:08 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. Dec 06 16:51:08 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. Dec 06 16:51:08 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. Dec 06 16:51:08 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. Dec 06 16:51:08 volumio sudo[15362]: pam_unix(sudo:session): session closed for user root Dec 06 16:51:08 volumio volumio[14828]: info: Remote SSH Stopped Dec 06 16:51:09 volumio volumio[14828]: info: Setting Geolocation for MyVolumio to us1 Dec 06 16:51:09 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:09 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:09 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:09 volumio volumio[14828]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 06 16:51:10 volumio volumio[14828]: info: Updating MyVolumio device info Dec 06 16:51:10 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:10 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:10 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:10 volumio volumio[14828]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 06 16:51:11 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:11 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 06 16:51:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:11 volumio go-librespot[15365]: go-librespot daemon starting... Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=debug msg="app state loaded" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06: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]" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06: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]" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06: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]" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=info msg="zeroconf server listening on port 44475" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=debug msg="obtained new client token: AAD+I81TQx//xWHVxBpcm6nITWcyYi9KDbDuvbmGtosBzjnKPhCrXtZIz+J/zv3+9x+b2oHN3uDX5KFqvsOGjEeLySbUkGAzHc5dC0OiEBVGlfk6tocE5ogAIMq000KZl+2+zJUsDZgn7skM9xxBzyQAS3IegkDjDTAahdMPfCD1NhaCNOxdKzaZJjNrEJkfQ7LKyH7B0zmPrUnGG1Z9QlCR1QJ56jScmDmYF5Mg+xAjGnTvgYWOAUXELA==" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=debug msg="completed challenge" Dec 06 16:51:12 volumio go-librespot[15366]: time="2025-12-06T16:51:12-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:13 volumio volumio[14828]: info: MYVOLUMIO: Adding device Dec 06 16:51:13 volumio volumio[14828]: info: MYVOLUMIO: Evaluating Server Dec 06 16:51:13 volumio volumio[14828]: info: Setting Geolocation for MyVolumio to us4 Dec 06 16:51:13 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:13 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:13 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:13 volumio volumio[14828]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 06 16:51:14 volumio volumio[14828]: info: Updating MyVolumio device info Dec 06 16:51:14 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:14 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:14 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:14 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:14 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:14 volumio volumio[14828]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 06 16:51:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 06 16:51:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:15 volumio go-librespot[15391]: go-librespot daemon starting... Dec 06 16:51:15 volumio go-librespot[15392]: time="2025-12-06T16:51:15-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:15 volumio go-librespot[15392]: time="2025-12-06T16:51:15-06:00" level=debug msg="app state loaded" Dec 06 16:51:15 volumio go-librespot[15392]: time="2025-12-06T16:51:15-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:15 volumio go-librespot[15392]: time="2025-12-06T16:51:15-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:15 volumio go-librespot[15392]: time="2025-12-06T16:51:15-06: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]" Dec 06 16:51:15 volumio go-librespot[15392]: time="2025-12-06T16:51:15-06: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]" Dec 06 16:51:15 volumio go-librespot[15392]: time="2025-12-06T16:51:15-06: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]" Dec 06 16:51:16 volumio go-librespot[15392]: time="2025-12-06T16:51:16-06:00" level=info msg="zeroconf server listening on port 44953" Dec 06 16:51:16 volumio go-librespot[15392]: time="2025-12-06T16:51:16-06:00" level=debug msg="obtained new client token: AACEzSrldOxM4QywLyotS8gnYepbxZ5EwHdpDkTy5YmK/Q7/XyOdLFHatvGkxoKkS9z/c3ZH61+cIdwvj+UzxI7lPNGr14HSz33RoVxgNArqpvA+eNc27dpwUAic74nTpzCT1cCRK2o0rFoawAxJDeFgTDHRfJP9RBKin786im43ccciKaZXO6o0/4x5KHszEbVOXa3gL5MvJjX155vXhH5TqBx6LrSXsj23xA0QC2HJ9BQF/asCcTU=" Dec 06 16:51:16 volumio go-librespot[15392]: time="2025-12-06T16:51:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:16 volumio go-librespot[15392]: time="2025-12-06T16:51:16-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:16 volumio go-librespot[15392]: time="2025-12-06T16:51:16-06:00" level=debug msg="completed challenge" Dec 06 16:51:16 volumio go-librespot[15392]: time="2025-12-06T16:51:16-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:17 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:17 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:18 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:51:18 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:18 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 06 16:51:19 volumio volumio-remote-updater[2353]: Test mode disabled Dec 06 16:51:19 volumio volumio-remote-updater[2353]: Alpha mode disabled Dec 06 16:51:19 volumio volumio-remote-updater[2353]: Alpha legacy test mode disabled Dec 06 16:51:19 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 06 16:51:19 volumio volumio[14828]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

ANNOUNCEMENT

\n
    \n
  • Production line
    • \n
\n

FIX

\n
    \n
  • Nodejs 20.5.1 version pinning with static package fallback
    • \n
\n","title":"Update v4.073","updateavailable":true} Dec 06 16:51:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 06 16:51:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:19 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 06 16:51:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:19 volumio go-librespot[15420]: go-librespot daemon starting... Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06:00" level=debug msg="app state loaded" Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06: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]" Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06: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]" Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06: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]" Dec 06 16:51:19 volumio go-librespot[15421]: time="2025-12-06T16:51:19-06:00" level=info msg="zeroconf server listening on port 35163" Dec 06 16:51:20 volumio go-librespot[15421]: time="2025-12-06T16:51:20-06:00" level=debug msg="obtained new client token: AAAvVkqsBuHIeUwQOFc99k5B/Y/AisGeUjJX6LLYt7nQz1YVjQjVUDCKUya0jlDbPa5vIHRGmlPg+ENB/6hmM4C50NbNbPRdGK+fvmNP1t3M/5B/DudvhueToOuhOgYTMYB2EHCiTzW4+pNflacrxJsyJvPKQTxaw7JnAKSONujSron+EJjREbGBfoBcZOAlpJtAHY74INczsWqEv//W0tHHRORXeY9x8DMBIAgdVA2nB1aYl6whzcM=" Dec 06 16:51:20 volumio go-librespot[15421]: time="2025-12-06T16:51:20-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:20 volumio go-librespot[15421]: time="2025-12-06T16:51:20-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:20 volumio go-librespot[15421]: time="2025-12-06T16:51:20-06:00" level=debug msg="completed challenge" Dec 06 16:51:20 volumio go-librespot[15421]: time="2025-12-06T16:51:20-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:20 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:20 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:21 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 06 16:51:21 volumio volumio[14828]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 06 16:51:21 volumio volumio[14828]: info: CoreCommandRouter::volumioGetState Dec 06 16:51:21 volumio volumio[14828]: info: CorePlayQueue::getTrack 0 Dec 06 16:51:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 06 16:51:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:23 volumio go-librespot[15429]: go-librespot daemon starting... Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=debug msg="app state loaded" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06: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]" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06: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]" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06: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]" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=info msg="zeroconf server listening on port 37361" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=debug msg="obtained new client token: AACEf0/WNyRdJKNue1BL/HSSASqLZy1S+t04eKV2EX81sW0jPS58g/bZ2brtb5+zdHK70zE8ToLYHMJ2ktqfW9Lj0c8lBv55IWZ/fxUu07Gpgw1ubdhyJ7m7r/pLhRapjQgIwdSEPnLjCDZ1ABWQZjZKvSZYC0Sy+y3NhQhdTGNkraLLbzQtmYlgTmJBEKkzhy8oWpc/gQy9947VbS5EtYLYik/UsiqcM0nR0ntz9u3KCVhuz/S8H4qaFw==" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=debug msg="completed challenge" Dec 06 16:51:23 volumio go-librespot[15430]: time="2025-12-06T16:51:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:23 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:23 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:26 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:51:26 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:51:26 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 06 16:51:26 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 06 16:51:26 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 06 16:51:26 volumio volumio[14828]: info: CoreCommandRouter::volumioGetBrowseSources Dec 06 16:51:26 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 16:51:26 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:26 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 06 16:51:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:26 volumio go-librespot[15453]: go-librespot daemon starting... Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=debug msg="app state loaded" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06: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]" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06: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]" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06: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]" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=info msg="zeroconf server listening on port 38025" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=debug msg="obtained new client token: AACUyVGSnAzpY/9kVDAon4R/1q0VP1h1FNkKbzLtHxQ4mv06ATJtp/StPOidu2SoqGEggvpsh7p3P4YbsUM2fzgwYXUH1vyg6wB2GN30avZ9YFi3Pp4J7dbWNX8apw2DIE6DApKyZzumpD165Bd3Fp0TTsGuO6zrt0XFRcvsrl4vDkwoSk9aHw4pwZK00IeAeUzIQABTKw2XaZwnEKcCdsjkXchgTj8VcTiuUIsf0SZnKlQd1Lbypo73FA==" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=debug msg="completed challenge" Dec 06 16:51:27 volumio go-librespot[15454]: time="2025-12-06T16:51:27-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:27 volumio volumio[14828]: error: MyVolumio Plugin failed to authenticate in a timely fashion Dec 06 16:51:27 volumio volumio[14828]: info: Completed starting MyVolumio Plugin Dec 06 16:51:27 volumio volumio[14828]: [Metrics] CommandRouter: 54s 82.39ms Dec 06 16:51:27 volumio volumio[14828]: info: CoreCommandRouter::volumiosetStartupVolume Dec 06 16:51:27 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 16:51:27 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 16:51:27 volumio volumio[14828]: info: CoreCommandRouter::Close All Modals sent Dec 06 16:51:27 volumio volumio[14828]: info: CoreCommandRouter::Close All Modals sent Dec 06 16:51:28 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 06 16:51:28 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 06 16:51:28 volumio volumio[14828]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 06 16:51:29 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:29 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Dec 06 16:51:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:30 volumio go-librespot[15467]: go-librespot daemon starting... Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06:00" level=debug msg="app state loaded" Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06: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]" Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06: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]" Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06: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]" Dec 06 16:51:30 volumio go-librespot[15468]: time="2025-12-06T16:51:30-06:00" level=info msg="zeroconf server listening on port 38717" Dec 06 16:51:31 volumio go-librespot[15468]: time="2025-12-06T16:51:31-06:00" level=debug msg="obtained new client token: AACuxHYldSFQPc3Ge8j0N8bwbnEbsYqxW3hPXH8dNQO8sH/YXWlnar+1Uq3OOtRPOPeSm5tLDKKpK3htfJxdTslRw1GPdMT+FC7WjeAQY3jtfkMR785uRImCDQlaS4y9mJgDdCYRiR+JPOZrGnVPMx1I8N3+/G26a+LFM9DCh7A7jFL3K779Ulcc18kWMMd1+Q0rU6OfDuQ6SL+BB6fSr813GH2kMWOIpL3yDV0eYzyybCciGxZ4vU0=" Dec 06 16:51:31 volumio go-librespot[15468]: time="2025-12-06T16:51:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:31 volumio go-librespot[15468]: time="2025-12-06T16:51:31-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:31 volumio go-librespot[15468]: time="2025-12-06T16:51:31-06:00" level=debug msg="completed challenge" Dec 06 16:51:31 volumio go-librespot[15468]: time="2025-12-06T16:51:31-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:32 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:32 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Dec 06 16:51:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:34 volumio go-librespot[15476]: go-librespot daemon starting... Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=debug msg="app state loaded" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06: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]" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06: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]" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06: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]" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=info msg="zeroconf server listening on port 39611" Dec 06 16:51:34 volumio volumio[14828]: info: BOOT COMPLETED Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=debug msg="obtained new client token: AAC1JYDkPegGvtrzrf4/YB32aknQhUjCb/gt6ANOiAnS9PyRiXiySq/Pf2041ktxoBDee0XoUQEvjDsxooajgsxRPM6VAm3IbZ1nB9vlGb6pYYJ1C1ZFKUbu9tuMohRldo/FZHpG/0UGLBCmPMwdR10Pn/wzBtIhF/cHh/6VNoBzSRO6jikEXky/nVrq1BCS/r93pZ5APUmOZ9oEYuZm/eBnVqUBreABoDUKjuPFaI2e+bhgjL08EkdfGg==" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=debug msg="completed challenge" Dec 06 16:51:34 volumio go-librespot[15477]: time="2025-12-06T16:51:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:35 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:35 volumio volumio[14828]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Dec 06 16:51:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:38 volumio go-librespot[15498]: go-librespot daemon starting... Dec 06 16:51:38 volumio go-librespot[15500]: time="2025-12-06T16:51:38-06:00" level=info msg="running go-librespot 0.4.0" Dec 06 16:51:38 volumio go-librespot[15500]: time="2025-12-06T16:51:38-06:00" level=debug msg="app state loaded" Dec 06 16:51:38 volumio go-librespot[15500]: time="2025-12-06T16:51:38-06:00" level=debug msg="stored credentials not found" Dec 06 16:51:38 volumio go-librespot[15500]: time="2025-12-06T16:51:38-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 16:51:38 volumio volumio[14828]: info: Initializing connection to go-librespot Websocket Dec 06 16:51:38 volumio go-librespot[15500]: time="2025-12-06T16:51:38-06:00" level=debug msg="new websocket client" Dec 06 16:51:38 volumio volumio[14828]: info: Connection to go-librespot Websocket established Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06: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]" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06: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]" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06: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]" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06:00" level=info msg="zeroconf server listening on port 36787" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06:00" level=debug msg="obtained new client token: AAA1tibJYT9KQ2FKgcPwpnqQrDfGMZvTgo2aFShO1Qtv+4qykSP3raEwBpgR0ymfrzC6Uocj682P3DZhXXXiblr+Ng8F3arw9zOA1vXb0Hf34l4F7H1no/8CPiZtOAJJwjbJnacFwYvOsUaF8zMyGVPPUgFsbVqsG/SujkF9CMPHw4ijb6CWnNc/MteqkhEXXSZCTHCLBMRKNxiZgzmI6Ltla6NupZV9rVld3NuyLxPQlsJD2lXAYmjgbw==" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06:00" level=debug msg="completed keyexchange" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06:00" level=debug msg="completed challenge" Dec 06 16:51:39 volumio go-librespot[15500]: time="2025-12-06T16:51:39-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 16:51:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 16:51:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 16:51:39 volumio volumio[14828]: info: Connection to go-librespot Websocket closed Dec 06 16:51:41 volumio volumio[14828]: info: Getting Spotify volume Dec 06 16:51:42 volumio volumio[14828]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:51:42 volumio volumio[14828]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 16:51:42 volumio volumio[14828]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 06 16:51:42 volumio volumio[14828]: errno: -111, Dec 06 16:51:42 volumio volumio[14828]: code: 'ECONNREFUSED', Dec 06 16:51:42 volumio volumio[14828]: syscall: 'connect', Dec 06 16:51:42 volumio volumio[14828]: address: '127.0.0.1', Dec 06 16:51:42 volumio volumio[14828]: port: 9879, Dec 06 16:51:42 volumio volumio[14828]: response: undefined Dec 06 16:51:42 volumio volumio[14828]: } Dec 06 16:51:42 volumio volumio[14828]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 16:51:42 volumio sudo[15523]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 16:50' Dec 06 16:51:42 volumio sudo[15523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 16:51:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Dec 06 16:51:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 16:51:42 volumio go-librespot[15525]: go-librespot daemon starting... 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="ac7dd5922ede329d1459d48b226ddc71f5209a2c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025" VOLUMIO_VERSION="4.069" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"