Dec 06 12:21:00 volumio volumio[11971]: info: Plugin calmradio is not enabled
Dec 06 12:21:00 volumio volumio[11971]: info: Loading plugin "soundcloud"...
Dec 06 12:21:00 volumio volumio[11971]: info: Loading plugin "spop"...
Dec 06 12:21:01 volumio volumio[11971]: info: Loading plugin "squeezelite_mc"...
Dec 06 12:21:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16.
Dec 06 12:21:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:01 volumio go-librespot[12059]: go-librespot daemon starting...
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-06:00" level=debug msg="app state loaded"
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-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 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-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 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-06:00" level=info msg="zeroconf server listening on port 43663"
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-06:00" level=debug msg="obtained new client token: AABnnUX/Ew5EotaLYcodKNRLakdmNZd9p9RJfj3zsH7ChiMccjzJoh4bmumJk1+tTz6tzf2nwV+O4b5PhaqjASSKX/vKdcwO1ux1QXoKL1aYDkJMsCdMoRalQDmnkOobSO/Rskt2JtOHBRT+UloEuVFIx/FBpeCpCaUAU/asOp1CQjpnq+l7NNL8b62USokmihGj74dBJ/eFk1ELbb7wOt+YLeX8w8Gtr8mu+NEyz38/RN+OYdiSG1N0HQ=="
Dec 06 12:21:01 volumio go-librespot[12060]: time="2025-12-06T12:21:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:02 volumio go-librespot[12060]: time="2025-12-06T12:21:02-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:02 volumio go-librespot[12060]: time="2025-12-06T12:21:02-06:00" level=debug msg="completed challenge"
Dec 06 12:21:02 volumio go-librespot[12060]: time="2025-12-06T12:21:02-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 12:21:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:02 volumio volumio[11971]: info: Loading plugin "youtube2"...
Dec 06 12:21:02 volumio volumio[11971]: info: Loading plugin "ytcr"...
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "ytmusic"...
Dec 06 12:21:04 volumio volumio[11971]: info: Plugin now_playing is not enabled
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "outputs"...
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "albumart"...
Dec 06 12:21:04 volumio volumio[11971]: info: Plugin example_plugin is not enabled
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "inputs"...
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "updater_comm"...
Dec 06 12:21:04 volumio volumio[11971]: info: Plugin mpdemulation is not enabled
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "rest_api"...
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "websocket"...
Dec 06 12:21:04 volumio volumio[11971]: info: Starting Socket.io Server version 1.7.4
Dec 06 12:21:04 volumio volumio[11971]: info: Plugin fusiondsp is not enabled
Dec 06 12:21:04 volumio volumio[11971]: info: Plugin mpdoutput is not enabled
Dec 06 12:21:04 volumio volumio[11971]: info: Plugin RoonBridge is not enabled
Dec 06 12:21:04 volumio volumio[11971]: info: Loading plugin "podcast"...
Dec 06 12:21:05 volumio volumio[11971]: info: ControllerPodcast::constructor
Dec 06 12:21:05 volumio volumio[11971]: info: Loading plugin "volusonic"...
Dec 06 12:21:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17.
Dec 06 12:21:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:05 volumio volumio[12070]: Forking 3 albumart workers
Dec 06 12:21:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:05 volumio go-librespot[12080]: go-librespot daemon starting...
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=debug msg="app state loaded"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-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 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-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 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-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 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=info msg="zeroconf server listening on port 40107"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=debug msg="obtained new client token: AAC9Od/M4FEGZetHcXjwpeIUlMD2OX1fPQ+2HzxdYGm4COui+dqaTR5HCcnfe6s49/hQThxeaG9lj+nXYb81JaelCFrlfanbaTy3AakkCwELcTZ1BG5YFLsD8lRUjyNd6dJ9/DUF2sCjit0i5jGqbQlKPGJObQe4Kxyx7WLUseVoIhLr/fu2K5qMNzLGogh/LZtyZGRBkWurocSq6OSIqdfO1dMGJ0Zfg/3Y7wQWhPHF9+rsf6ZqNvQcBw=="
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-06:00" level=debug msg="completed challenge"
Dec 06 12:21:05 volumio go-librespot[12099]: time="2025-12-06T12:21:05-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 12:21:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:06 volumio volumio[11971]: info: Applying required configuration parameters for plugin volusonic
Dec 06 12:21:06 volumio volumio[11971]: info: Loading plugin "backup_restore"...
Dec 06 12:21:07 volumio volumio[12082]: Starting albumart workers
Dec 06 12:21:07 volumio volumio[11971]: info: Applying required configuration parameters for plugin backup_restore
Dec 06 12:21:07 volumio volumio[12081]: Starting albumart workers
Dec 06 12:21:07 volumio volumio[11971]: info: Plugin rpi_eeprom_config is not enabled
Dec 06 12:21:07 volumio volumio[11971]: info: Plugin rpi_eeprom_updater is not enabled
Dec 06 12:21:07 volumio volumio[11971]: info: Loading plugin "scheduledrestart"...
Dec 06 12:21:07 volumio volumio[12083]: Starting albumart workers
Dec 06 12:21:07 volumio volumio[11971]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 06 12:21:07 volumio volumio[11971]: info: Plugin Bluetoothremote is not enabled
Dec 06 12:21:07 volumio volumio[11971]: info: Plugin music_services_shield is not enabled
Dec 06 12:21:07 volumio volumio[11971]: info: Loading plugin "Systeminfo"...
Dec 06 12:21:07 volumio volumio[11971]: info: Plugin peppymeterbasic is not enabled
Dec 06 12:21:07 volumio volumio[11971]: info: Loading plugin "peppyspectrum"...
Dec 06 12:21:08 volumio volumio[11971]: info: Loading i18n strings for locale en
Dec 06 12:21:08 volumio volumio[11971]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 06 12:21:08 volumio volumio[11971]: Updating browse sources language
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::initPlayerControls
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: Express server listening on port 3000
Dec 06 12:21:08 volumio volumio[11971]:  [Metrics]  WebUI:  14s 591.41ms 
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::resetVolumioState
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::getcurrentVolume
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioRetrievevolume
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:08 volumio sudo[12156]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 06 12:21:08 volumio sudo[12156]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:08 volumio sudo[12158]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 06 12:21:08 volumio sudo[12156]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:08 volumio sudo[12158]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:08 volumio sudo[12158]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:08 volumio volumio[11971]: info: Volumio Network Manager: Network status updated: 1
Dec 06 12:21:08 volumio volumio[11971]: info: VolumeController:: Volume=86 Mute =false
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::pushState
Dec 06 12:21:08 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioPushState
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::updateTrackBlock
Dec 06 12:21:08 volumio volumio[11971]: info: CorePlayQueue::getTrackBlock
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioRetrievevolume
Dec 06 12:21:08 volumio volumio[11971]: info: Reloading queue from file
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::setRepeat null single undefined
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::pushState
Dec 06 12:21:08 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioPushState
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::setRandom null
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::pushState
Dec 06 12:21:08 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioPushState
Dec 06 12:21:08 volumio volumio[11971]: info: Setting Device type: Raspberry PI
Dec 06 12:21:08 volumio volumio[11971]: info: VolumeController:: Volume=86 Mute =false
Dec 06 12:21:08 volumio volumio[11971]: info: CoreStateMachine::pushState
Dec 06 12:21:08 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioPushState
Dec 06 12:21:08 volumio volumio[11971]: info: Completed loading Core Plugins
Dec 06 12:21:08 volumio volumio[11971]: info: Preparing to generate the ALSA configuration file
Dec 06 12:21:08 volumio sudo[12172]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 06 12:21:08 volumio sudo[12172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:08 volumio volumio[11971]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 06 12:21:08 volumio volumio[11971]: info: Discovery: Found device Volumio
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:08 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:08 volumio volumio[11971]: info: Discovery: this is already registered,  a135e40e-a404-457b-98f5-36bf71c75954
Dec 06 12:21:08 volumio volumio[11971]: info: Discovery: Found device Volumio
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:08 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:08 volumio volumio[11971]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 06 12:21:08 volumio volumio[11971]: info: Reading ALSA contributions from plugins.
Dec 06 12:21:08 volumio volumio[11971]: info: Asound.conf file unchanged, so no further update is needed
Dec 06 12:21:08 volumio volumio[11971]: info: Output device has changed, restarting MPD
Dec 06 12:21:08 volumio sudo[12172]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:08 volumio volumio[11971]: info: Output device has changed, restarting Shairport Sync
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:08 volumio sudo[12175]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 06 12:21:08 volumio sudo[12175]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:08 volumio sudo[12175]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:08 volumio sudo[12177]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 06 12:21:08 volumio sudo[12177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:08 volumio volumio[11971]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:21:08 volumio volumio[11971]: info: ___________ START PLUGINS ___________
Dec 06 12:21:08 volumio volumio[11971]: info: ControllerMpd::onStart: Initializing MPD
Dec 06 12:21:08 volumio volumio[11971]: info: Creating MPD Configuration file
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:08 volumio volumio[11971]: info: [1765045268806] CoreMusicLibrary::Adding element Media Servers
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:08 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 06 12:21:08 volumio sudo[12185]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 06 12:21:08 volumio sudo[12185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:08 volumio sudo[12187]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 06 12:21:08 volumio sudo[12187]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:08 volumio sudo[12185]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:08 volumio volumio[11971]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:08 volumio volumio[11971]: info: [1765045268921] CoreMusicLibrary::Adding element Last_100
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:08 volumio volumio[11971]: info: [1765045268925] CoreMusicLibrary::Adding element Webradio
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:08 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 06 12:21:08 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 06 12:21:08 volumio systemd[1]: mpd.service: Consumed 4.555s CPU time.
Dec 06 12:21:08 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 06 12:21:08 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 06 12:21:08 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 06 12:21:08 volumio volumio[11971]: info: Initializing BBC Radios
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 06 12:21:08 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:08 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:09 volumio volumio[11971]: info: [1765045269005] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 06 12:21:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18.
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:09 volumio volumio[11971]: info: [1765045269019] CoreMusicLibrary::Adding element SoundCloud
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:09 volumio volumio[11971]: info: Creating Spotify config file
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:09 volumio go-librespot[12213]: go-librespot daemon starting...
Dec 06 12:21:09 volumio go-librespot[12214]: time="2025-12-06T12:21:09-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:09 volumio sudo[12212]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 06 12:21:09 volumio sudo[12212]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 06 12:21:09 volumio sudo[12212]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:09 volumio go-librespot[12214]: time="2025-12-06T12:21:09-06:00" level=info msg="zeroconf server listening on port 34601"
Dec 06 12:21:09 volumio volumio-remote-updater[2353]: [2025-12-06 12:21:09] [connect] Successful connection
Dec 06 12:21:09 volumio volumio[11971]: info: [squeezelite_mc] Starting proxy server...
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:09 volumio volumio[11971]: info: [1765045269407] CoreMusicLibrary::Adding element YouTube2
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube2
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:09 volumio volumio[11971]: info: [1765045269426] CoreMusicLibrary::Adding element YouTube Music
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube2
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube Music
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:09 volumio volumio[11971]: info: [1765045269438] CoreMusicLibrary::Adding element Podcast
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube2
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube Music
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Podcast
Dec 06 12:21:09 volumio volumio[11971]: info: Loading i18n strings for locale en
Dec 06 12:21:09 volumio volumio[11971]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 06 12:21:09 volumio volumio[11971]: Updating browse sources language
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube2
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube Music
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Podcast
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube2
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube Music
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Podcast
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:09 volumio volumio[11971]: info: [1765045269493] CoreMusicLibrary::Adding element Volusonic
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube2
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source YouTube Music
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Podcast
Dec 06 12:21:09 volumio volumio[11971]: Cannot find translation for source Volusonic
Dec 06 12:21:09 volumio volumio[11971]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 06 12:21:09 volumio volumio[11971]: info: Volumio Calling Home
Dec 06 12:21:09 volumio volumio[11971]: info: [squeezelite_mc] Proxy server started on port 45635
Dec 06 12:21:09 volumio volumio[11971]: info: Preparing to generate the ALSA configuration file
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioRetrievevolume
Dec 06 12:21:09 volumio volumio[11971]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 06 12:21:09 volumio volumio[11971]: info: Reading ALSA contributions from plugins.
Dec 06 12:21:09 volumio volumio[11971]: info: MPD Permissions set
Dec 06 12:21:09 volumio volumio[11971]: info: MPD Permissions set
Dec 06 12:21:09 volumio volumio[11971]: info: Upmpdcli Daemon Started
Dec 06 12:21:09 volumio volumio-remote-updater[2353]: [2025-12-06 12:21:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765045269 101
Dec 06 12:21:09 volumio volumio[11971]: 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 12:21:09 volumio volumio[11971]: info: Spotify config file written
Dec 06 12:21:09 volumio sudo[12230]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 06 12:21:09 volumio sudo[12230]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:09 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon...
Dec 06 12:21:09 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully.
Dec 06 12:21:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:09 volumio volumio[11971]: 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 12:21:09 volumio volumio[11971]: info: VolumeController:: Volume=86 Mute =false
Dec 06 12:21:09 volumio volumio[11971]: info: CoreStateMachine::pushState
Dec 06 12:21:09 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:09 volumio volumio[11971]: info: CoreCommandRouter::volumioPushState
Dec 06 12:21:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:09 volumio go-librespot[12232]: go-librespot daemon starting...
Dec 06 12:21:10 volumio sudo[12230]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:10 volumio volumio[11971]: info: [squeezelite_mc] Server discovery started
Dec 06 12:21:10 volumio volumio[11971]: info: [squeezelite_mc] Player finder started
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero  2>&1 || true
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=debug msg="app state loaded"
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: No need to fix Spotify hosts
Dec 06 12:21:10 volumio volumio[11971]: 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 12:21:10 volumio volumio[11971]: info: Volumio called home
Dec 06 12:21:10 volumio volumio[11971]: 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 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-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 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-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 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-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 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=info msg="zeroconf server listening on port 38647"
Dec 06 12:21:10 volumio volumio[11971]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 06 12:21:10 volumio volumio[11971]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 06 12:21:10 volumio volumio[11971]: 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 12:21:10 volumio volumio[11971]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 06 12:21:10 volumio volumio[11971]: SPOTIFY: BQBFQuiqLCdeae0OpO5Z62vs3yXSTA0T6lyMaGk7Vy8O66lgwzRHvmMDMNx_AM1bRZCUar_Dp8tPX1d2DMp_OaGtn_P2kfaUKzKoiTXDjUthrIVsjR80f-JJijhMJJqinmFWYmQ4zXbDF4zdBXR_5ycDQVZRSDEpImbsQpiJK7wD9X_sf-9lJfDkW8Q8EAKLhoH3yElK3t1wawdJfkhjHGcZB5RWXl1fpRLvjw8
Dec 06 12:21:10 volumio volumio[11971]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 06 12:21:10 volumio volumio[11971]: info: New Spotify access token = BQBFQuiqLCdeae0OpO5Z62vs3yXSTA0T6lyMaGk7Vy8O66lgwzRHvmMDMNx_AM1bRZCUar_Dp8tPX1d2DMp_OaGtn_P2kfaUKzKoiTXDjUthrIVsjR80f-JJijhMJJqinmFWYmQ4zXbDF4zdBXR_5ycDQVZRSDEpImbsQpiJK7wD9X_sf-9lJfDkW8Q8EAKLhoH3yElK3t1wawdJfkhjHGcZB5RWXl1fpRLvjw8
Dec 06 12:21:10 volumio volumio[11971]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 06 12:21:10 volumio volumio[11971]: info: Starting Shairport Sync
Dec 06 12:21:10 volumio volumio[11971]: info: Starting Shairport Sync
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=debug msg="obtained new client token: AACZ6iQ9fhSbPpS9Qxmsbdj2NRaoNA5qxmdPMEyyi1R6pSbdDidYFFl8rdG2QgZN8O1XYrXVyyduzcg83ZkGFLLXZZGe2tan9JdCBEhRU9wORknpiYcAdqaYeM97re8fUUiPGnZOwjQpvth1VhQwb0XTVqx5MXkDd3dZVHrnh7G8uDbNA9hxFxHOnIay2+OkJ+zoAyGCMw5Y4XA179FT4x8Z0lhd3nyKeOyvw67yZebNK7WOpytOCeNuVw=="
Dec 06 12:21:10 volumio volumio[11971]: info: Starting Shairport Sync
Dec 06 12:21:10 volumio sudo[12257]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:21:10 volumio sudo[12257]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:10 volumio sudo[12260]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:21:10 volumio sudo[12260]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:10 volumio sudo[12261]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:21:10 volumio sudo[12261]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:10 volumio sudo[12254]:  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 12:21:10 volumio sudo[12254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:10 volumio sudo[12254]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:10 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 06 12:21:10 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 06 12:21:10 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:21:10 volumio systemd[1]: shairport-sync.service: Consumed 2.014s CPU time.
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-06:00" level=debug msg="completed challenge"
Dec 06 12:21:10 volumio go-librespot[12233]: time="2025-12-06T12:21:10-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 12:21:10 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:21:10 volumio sudo[12257]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:10 volumio volumio[11971]: info: Asound.conf file unchanged, so no further update is needed
Dec 06 12:21:10 volumio volumio[11971]: info: Output device has changed, restarting MPD
Dec 06 12:21:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:10 volumio volumio[11971]: info: Output device has changed, restarting Shairport Sync
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:10 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:10 volumio sudo[12272]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 06 12:21:10 volumio sudo[12272]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:10 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 06 12:21:10 volumio volumio[11971]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:21:10 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 06 12:21:10 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:21:10 volumio sudo[12268]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 06 12:21:10 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:21:10 volumio sudo[12261]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:10 volumio sudo[12268]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:10 volumio sudo[12268]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:10 volumio sudo[12260]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:10 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 06 12:21:10 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 06 12:21:10 volumio systemd[1]: mpd.service: Consumed 1.666s CPU time.
Dec 06 12:21:10 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 06 12:21:10 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 06 12:21:10 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 06 12:21:10 volumio volumio[11971]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 06 12:21:10 volumio sudo[12307]:  volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 06 12:21:10 volumio sudo[12307]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:10 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 06 12:21:10 volumio sudo[12307]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:11 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 06 12:21:11 volumio volumio[11971]: info: MPD Permissions set
Dec 06 12:21:11 volumio volumio[11971]: info: Shairport-Sync Started
Dec 06 12:21:11 volumio volumio[11971]: Error adding Membership: Error: addMembership EINVAL
Dec 06 12:21:11 volumio volumio[11971]: info: Shairport-Sync Started
Dec 06 12:21:11 volumio volumio[11971]: info: Shairport-Sync Started
Dec 06 12:21:11 volumio volumio[11971]: 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 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:11 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:11 volumio volumio[11971]: info: Starting Shairport Sync
Dec 06 12:21:11 volumio sudo[12320]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:21:11 volumio sudo[12320]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:11 volumio sudo[12313]:  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 12:21:11 volumio volumio[11971]: 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 12:21:11 volumio sudo[12313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:11 volumio volumio[11971]: info: Spotify Successfully logged in
Dec 06 12:21:11 volumio sudo[12310]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:21:11 volumio volumio[11971]: info: [1765045271257] CoreMusicLibrary::Adding element Spotify
Dec 06 12:21:11 volumio sudo[12310]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 06 12:21:11 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:21:11 volumio volumio[11971]: Cannot find translation for source Bandcamp Discover
Dec 06 12:21:11 volumio sudo[12313]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:11 volumio volumio[11971]: Cannot find translation for source SoundCloud
Dec 06 12:21:11 volumio volumio[11971]: Cannot find translation for source YouTube2
Dec 06 12:21:11 volumio volumio[11971]: Cannot find translation for source YouTube Music
Dec 06 12:21:11 volumio volumio[11971]: Cannot find translation for source Podcast
Dec 06 12:21:11 volumio volumio[11971]: Cannot find translation for source Volusonic
Dec 06 12:21:11 volumio volumio[11971]: Cannot find translation for source Spotify
Dec 06 12:21:11 volumio sudo[12310]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:11 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload  || true
Dec 06 12:21:11 volumio sudo[12326]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 06 12:21:11 volumio sudo[12326]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:11 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 06 12:21:11 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 06 12:21:11 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:21:11 volumio systemd[1]: Reloading.
Dec 06 12:21:11 volumio volumio[11971]: info: [squeezelite_mc] Notification listener started
Dec 06 12:21:11 volumio volumio[11971]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 06 12:21:11 volumio volumio[11971]: 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 12:21:11 volumio volumio[11971]: 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 12:21:12 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:12 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:12 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:12 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:21:13 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 12:21:13 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 12:21:13 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:13 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:13 volumio sudo[12326]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:13 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:21:13 volumio volumio[11971]: info: go-librespot daemon successfully initialized
Dec 06 12:21:13 volumio sudo[12346]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:21:13 volumio sudo[12346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:13 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:21:13 volumio sudo[12320]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:13 volumio volumio[11971]: info: Shairport-Sync Started
Dec 06 12:21:13 volumio sudo[12346]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:13 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 06 12:21:13 volumio sudo[12364]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 06 12:21:13 volumio sudo[12364]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:13 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 06 12:21:13 volumio volumio[11971]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 06 12:21:13 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:13 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:13 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 06 12:21:13 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 06 12:21:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1.
Dec 06 12:21:13 volumio sudo[12364]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:14 volumio go-librespot[12366]: go-librespot daemon starting...
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=debug msg="app state loaded"
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-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 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-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 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-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 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=info msg="zeroconf server listening on port 32843"
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=debug msg="obtained new client token: AABfIWOGc3JTxKntvAAQDdDXKXAGV2X5mK1F4ZBSWY1eHjmVXERWbPvs9GxgIFZxCitjhe9Wl0mmJk3h7NLSRkKRAmNCUqzqYo372YdVD8fVeqB3Nh2BifpCxmYSApp2msH+V+Wh+MVfRbEEG8sfyKpEr3y92kIj2yA70hVahSW9OmuNTK1hEXrj9J8nCo2wyvY9aH/y1pyyVY2A+kWNsVk1mbBmzoww9U+u7+h9FHzKVecOyrrz2aeSkQ=="
Dec 06 12:21:14 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:21:14 volumio sudo[12376]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:21:14 volumio sudo[12376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-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 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=debug msg="connected to ap-guc3.spotify.com:443"
Dec 06 12:21:14 volumio sudo[12376]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:14 volumio volumio[11971]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-06:00" level=debug msg="completed challenge"
Dec 06 12:21:14 volumio sudo[12380]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 06 12:21:14 volumio sudo[12380]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:14 volumio sudo[12380]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:14 volumio go-librespot[12367]: time="2025-12-06T12:21:14-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 12:21:14 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 06 12:21:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:14 volumio sudo[12383]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 06 12:21:14 volumio sudo[12383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:14 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 06 12:21:14 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 06 12:21:14 volumio sudo[12383]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:14 volumio volumio[11971]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 06 12:21:14 volumio volumio[11971]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 06 12:21:14 volumio volumio[11971]: 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 12:21:14 volumio volumio[11971]: 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 12:21:15 volumio mpd[12324]: 2025-12-06T12:21:15 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 06 12:21:15 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 06 12:21:15 volumio sudo[12272]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:15 volumio sudo[12187]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:15 volumio sudo[12177]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:15 volumio volumio[11971]: error: MPD error: The expression evaluated to a falsy value:
Dec 06 12:21:15 volumio volumio[11971]:   assert.ok(self.idling)
Dec 06 12:21:15 volumio volumio[11971]: error: The expression evaluated to a falsy value:
Dec 06 12:21:15 volumio volumio[11971]:   assert.ok(self.idling)
Dec 06 12:21:15 volumio volumio[11971]: error: MPD error: The expression evaluated to a falsy value:
Dec 06 12:21:15 volumio volumio[11971]:   assert.ok(self.idling)
Dec 06 12:21:15 volumio volumio[11971]: error: The expression evaluated to a falsy value:
Dec 06 12:21:15 volumio volumio[11971]:   assert.ok(self.idling)
Dec 06 12:21:15 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:21:15 volumio volumio[11971]: error: updateQueue error: null
Dec 06 12:21:15 volumio volumio[11971]: info: MPD running with PID12324
Dec 06 12:21:15 volumio volumio[11971]:  ,establishing connection
Dec 06 12:21:15 volumio volumio[11971]: error: updateQueue error: null
Dec 06 12:21:15 volumio sudo[12394]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:21:15 volumio sudo[12394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:15 volumio sudo[12394]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:16 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:21:16 volumio sudo[12397]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:21:16 volumio sudo[12397]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:16 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:16 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:16 volumio sudo[12397]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:16 volumio volumio[11971]: info: Initializing connection to go-librespot Websocket
Dec 06 12:21:16 volumio volumio[11971]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:21:16 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:21:16 volumio sudo[12414]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:21:16 volumio sudo[12414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:16 volumio sudo[12414]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:17 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:21:17 volumio sudo[12417]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:21:17 volumio sudo[12417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:17 volumio sudo[12417]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2.
Dec 06 12:21:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:17 volumio go-librespot[12419]: go-librespot daemon starting...
Dec 06 12:21:17 volumio volumio[11971]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:21:17 volumio go-librespot[12420]: time="2025-12-06T12:21:17-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:17 volumio go-librespot[12420]: time="2025-12-06T12:21:17-06:00" level=debug msg="app state loaded"
Dec 06 12:21:17 volumio go-librespot[12420]: time="2025-12-06T12:21:17-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:17 volumio go-librespot[12420]: time="2025-12-06T12:21:17-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:17 volumio sudo[12428]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:21:17 volumio sudo[12428]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:17 volumio sudo[12428]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:17 volumio volumio[11971]: info: Completed starting Core Plugins
Dec 06 12:21:17 volumio volumio[11971]: info: -------------------------------------------
Dec 06 12:21:17 volumio volumio[11971]: info: -----    MyVolumio plugins startup     ----
Dec 06 12:21:17 volumio volumio[11971]: info: -------------------------------------------
Dec 06 12:21:17 volumio volumio[11971]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 06 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21: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-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 06 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21:18-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 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21:18-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 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21:18-06:00" level=info msg="zeroconf server listening on port 38705"
Dec 06 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21:18-06:00" level=debug msg="obtained new client token: AABUaW59XUVsJxrFEUYlGeIRS363mrHDvkQhc29X/UxjMLrmD6zcwhyMTg38OPxCMJEL2MYjlupQX/2oWTMANJUPn2fb74D2kDIUrikGIS17lpkI0zsiVV08lEdkKVoIOZ+b+3VIBGdzO5Ag4CNSQf3YMPPrNlGqI24sZtBtQSc6dkpYwD5sho7WOjZx7MsqWUSnoma5Bc5F7tB7S+6qWzUWlRDF0py75v7hU+omLQ2Kz/jCN5LGco8="
Dec 06 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21:18-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21:18-06:00" level=debug msg="completed challenge"
Dec 06 12:21:18 volumio go-librespot[12420]: time="2025-12-06T12:21: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 12:21:18 volumio sudo[12431]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 06 12:21:18 volumio sudo[12431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:18 volumio sudo[12433]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 06 12:21:18 volumio sudo[12433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:18 volumio sudo[12435]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 06 12:21:18 volumio sudo[12435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:18 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 06 12:21:18 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 06 12:21:18 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 06 12:21:18 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 06 12:21:18 volumio sudo[12433]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:18 volumio mpd_monitor.sh[12439]: MPD Monitor Service: Starting MPD Monitor Service
Dec 06 12:21:18 volumio sudo[12431]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:18 volumio sudo[12435]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:18 volumio volumio[11971]: info: Successfully started MPD Monitor
Dec 06 12:21:18 volumio volumio[11971]: info: Successfully started MPD Monitor
Dec 06 12:21:18 volumio volumio[11971]: info: Successfully started MPD Monitor
Dec 06 12:21:19 volumio volumio[11971]: info: Initializing connection to go-librespot Websocket
Dec 06 12:21:19 volumio volumio[11971]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:21:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3.
Dec 06 12:21:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:21 volumio go-librespot[12443]: go-librespot daemon starting...
Dec 06 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-06:00" level=debug msg="app state loaded"
Dec 06 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-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 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-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 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-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 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-06:00" level=info msg="zeroconf server listening on port 32805"
Dec 06 12:21:21 volumio go-librespot[12444]: time="2025-12-06T12:21:21-06:00" level=debug msg="obtained new client token: AABnR8jcw3gDD9plrq3n62enAd6WL+HCDx+8wswt7RUBH54BerR2a3AVHUxLzwcyVMukA4G3CWZbxYZg61jSSUh+xYM14Zmlj4KwE3hlk/LN8s3ezGwbOLKHi3LkGHHYKuDInqoX2YT9AeAh7HZEXeGYx5T2fhQWhZFJ9ZVwb+tQX65l1+cqf4Dkx9npAMg2q86cW22nlYPpXHMrDrWbU/kVzBws1JM1RlFwxtU3NDwJ3Wnonq/mmi9NhA=="
Dec 06 12:21:22 volumio go-librespot[12444]: time="2025-12-06T12:21:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:22 volumio go-librespot[12444]: time="2025-12-06T12:21:22-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:22 volumio go-librespot[12444]: time="2025-12-06T12:21:22-06:00" level=debug msg="completed challenge"
Dec 06 12:21:22 volumio go-librespot[12444]: time="2025-12-06T12:21:22-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 12:21:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:23 volumio volumio[11971]: info: Initializing connection to go-librespot Websocket
Dec 06 12:21:23 volumio volumio[11971]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:21:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4.
Dec 06 12:21:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:25 volumio go-librespot[12452]: go-librespot daemon starting...
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=debug msg="app state loaded"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-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 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-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 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-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 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=info msg="zeroconf server listening on port 40771"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=debug msg="obtained new client token: AADvoraehCHcMBF2O68sj6iqVdZlV+X9ZqFCAkRusPN5xLCf9PqlP3oNuUtNT3tPYdfZhwFiXavAoC/OrAy43B7BdJ6dzqQrLh3yq7VV/cAwqENViOEm2LmXvvpfvVxO81cfwuUtUT1qlNy12hFMhx3ccqTXvZ+vosx1YEHEJsuI9cBPosU4I5AbP7Nj0yH/xgsKt3tyY8EjMhvaWmjhbr3o9XB7tHVTiNWQ7WzpVz7FqafoT1bM/cdMxQ=="
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-06:00" level=debug msg="completed challenge"
Dec 06 12:21:25 volumio go-librespot[12453]: time="2025-12-06T12:21:25-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 12:21:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 06 12:21:26 volumio volumio[11971]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 06 12:21:26 volumio volumio[11971]: info: Adding plugin multiroom to MyMusic Plugins
Dec 06 12:21:26 volumio volumio[11971]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 06 12:21:26 volumio volumio[11971]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 06 12:21:26 volumio volumio[11971]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 06 12:21:26 volumio volumio[11971]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 06 12:21:26 volumio volumio[11971]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 06 12:21:26 volumio volumio[11971]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 06 12:21:27 volumio volumio[11971]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 06 12:21:27 volumio volumio[11971]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 06 12:21:27 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:27 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:27 volumio volumio[11971]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 06 12:21:27 volumio volumio[11971]: info: MyVolumio login type: Token
Dec 06 12:21:27 volumio volumio[11971]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 06 12:21:27 volumio volumio[11971]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 06 12:21:27 volumio volumio[11971]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 06 12:21:27 volumio volumio[11971]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 06 12:21:27 volumio volumio[11971]: info: Streaming services startup
Dec 06 12:21:27 volumio volumio[11971]: info: Starting Streaming Daemon
Dec 06 12:21:28 volumio sudo[12475]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 06 12:21:28 volumio sudo[12475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:28 volumio volumio[11971]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 06 12:21:28 volumio sudo[12475]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:28 volumio volumio[11971]: info: Initializing connection to go-librespot Websocket
Dec 06 12:21:28 volumio volumio[11971]: error: Cannot start Volumio Streaming Daemon
Dec 06 12:21:28 volumio volumio[11971]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 06 12:21:28 volumio volumio[11971]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 06 12:21:28 volumio volumio[11971]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:21:28 volumio volumio[11971]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 06 12:21:28 volumio volumio[11971]: info: MyVolumio token set successfully
Dec 06 12:21:28 volumio volumio[11971]: info: MYVOLUMIO: Adding device
Dec 06 12:21:28 volumio volumio[11971]: info: MYVOLUMIO: Evaluating Server
Dec 06 12:21:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5.
Dec 06 12:21:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:29 volumio go-librespot[12483]: go-librespot daemon starting...
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=debug msg="app state loaded"
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:29 volumio volumio[11971]: info: MyVolumio status changed
Dec 06 12:21:29 volumio volumio[11971]: info: Streaming services startup
Dec 06 12:21:29 volumio volumio[11971]: info: Starting Streaming Daemon
Dec 06 12:21:29 volumio volumio[11971]: info: Removing browser output: myVolumio user plan is not superstar
Dec 06 12:21:29 volumio volumio[11971]: info: Removing audio output:
Dec 06 12:21:29 volumio volumio[11971]: info: Stoppping Tunnel 1
Dec 06 12:21:29 volumio sudo[12509]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 06 12:21:29 volumio sudo[12509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:29 volumio sudo[12511]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 06 12:21:29 volumio sudo[12511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:29 volumio sudo[12509]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:29 volumio volumio[11971]: error: Cannot start Volumio Streaming Daemon
Dec 06 12:21:29 volumio volumio[11971]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 06 12:21:29 volumio volumio[11971]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 06 12:21:29 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 12:21:29 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 12:21:29 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 12:21:29 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 12:21:29 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 12:21:29 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 12:21:29 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 12:21:29 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 12:21:29 volumio sudo[12511]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:29 volumio volumio[11971]: info: Remote SSH Stopped
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-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 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-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 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-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 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=info msg="zeroconf server listening on port 42295"
Dec 06 12:21:29 volumio volumio[11971]: info: Setting Geolocation for MyVolumio to us4
Dec 06 12:21:29 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:29 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:29 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=debug msg="obtained new client token: AAAigs+Usf0V6SLgEbrzvXsgIertQPc0iEQ7UwUblHhHHxRqhwWiNe5Cf0H/bVTkGYg2Asby5HZG8sIXbq8YpTnEXVUiMYBnm0mPYON2ibKbFPelDklee/MU21oCsRUWcoZMm6I0PdULNEREeb6i1HhPGFk9DxPc4iAh+3/1F0+QeqL6+k0CaEdGh4WcMtyVR1FmjM4lyrTNwaz8zt1Z1+EqcDY4029Mfg1VckCATnk78AN/zWZKxnOlXQ=="
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-06:00" level=debug msg="completed challenge"
Dec 06 12:21:29 volumio go-librespot[12490]: time="2025-12-06T12:21:29-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 12:21:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:29 volumio volumio[11971]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 06 12:21:30 volumio volumio[11971]: info: Updating MyVolumio device info
Dec 06 12:21:30 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:30 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:30 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:30 volumio volumio[11971]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 06 12:21:31 volumio volumio[11971]: info: Initializing connection to go-librespot Websocket
Dec 06 12:21:31 volumio volumio[11971]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:21:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6.
Dec 06 12:21:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:32 volumio go-librespot[12517]: go-librespot daemon starting...
Dec 06 12:21:32 volumio go-librespot[12518]: time="2025-12-06T12:21:32-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:32 volumio go-librespot[12518]: time="2025-12-06T12:21:32-06:00" level=debug msg="app state loaded"
Dec 06 12:21:32 volumio go-librespot[12518]: time="2025-12-06T12:21:32-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:32 volumio go-librespot[12518]: time="2025-12-06T12:21:32-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 06 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-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 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-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 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-06:00" level=info msg="zeroconf server listening on port 36769"
Dec 06 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-06:00" level=debug msg="obtained new client token: AABgcUn0E49sLhNawelX3gMOKZmEvQd65Gy4byd+vxMcgXcOLT81T4a7H9WETkwsHz6Vcsp5apoq9NWVKDEb046LIalc3UUudSsPZBjSmAijSDuwy6P+xCMk3XeROyxsqHGLC0/qchhVB89KmrR3BgirW+iOkwp454PbqnsniKA8jhGhUN0Wrwxn2IOHQQBZSeiTU+6HnMwlnu7eFse48t+6J7NFsLAQGf9UgyXBIloNSi22vLpE+Dg="
Dec 06 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-06:00" level=debug msg="completed challenge"
Dec 06 12:21:33 volumio go-librespot[12518]: time="2025-12-06T12:21:33-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 12:21:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:33 volumio volumio[11971]: info: MYVOLUMIO: Adding device
Dec 06 12:21:33 volumio volumio[11971]: info: MYVOLUMIO: Evaluating Server
Dec 06 12:21:34 volumio volumio[11971]: info: Initializing connection to go-librespot Websocket
Dec 06 12:21:34 volumio volumio[11971]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:21:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7.
Dec 06 12:21:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:36 volumio go-librespot[12543]: go-librespot daemon starting...
Dec 06 12:21:36 volumio go-librespot[12544]: time="2025-12-06T12:21:36-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:36 volumio go-librespot[12544]: time="2025-12-06T12:21:36-06:00" level=debug msg="app state loaded"
Dec 06 12:21:36 volumio go-librespot[12544]: time="2025-12-06T12:21:36-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:36 volumio go-librespot[12544]: time="2025-12-06T12:21:36-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:37 volumio volumio[11971]: info: Initializing connection to go-librespot Websocket
Dec 06 12:21:37 volumio go-librespot[12544]: time="2025-12-06T12:21:37-06:00" level=debug msg="new websocket client"
Dec 06 12:21:37 volumio volumio[11971]: info: Connection to go-librespot Websocket established
Dec 06 12:21:39 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 06 12:21:39 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:39 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 06 12:21:39 volumio volumio-remote-updater[2353]: Test mode disabled
Dec 06 12:21:39 volumio volumio-remote-updater[2353]: Alpha mode disabled
Dec 06 12:21:39 volumio volumio-remote-updater[2353]: Alpha legacy test mode disabled
Dec 06 12:21:39 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 06 12:21:40 volumio volumio[11971]: info: Getting Spotify volume
Dec 06 12:21:40 volumio volumio[11971]: 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 12:21:40 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:40 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:40 volumio volumio[11971]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86
Dec 06 12:21:40 volumio volumio[11971]: SPOTIFY: SPOTIFY VOLUME undefined
Dec 06 12:21:40 volumio volumio[11971]: SPOTIFY: VOLUMIO VOLUME 86
Dec 06 12:21:40 volumio volumio[11971]: info: Aligning Spotify Volume to Volumio Volume
Dec 06 12:21:40 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:40 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:40 volumio volumio[11971]: info: Setting Spotify Volume from Volumio: 86
Dec 06 12:21:41 volumio volumio[11971]: SPOTIFY: SETTING SPOTIFY VOLUME 86
Dec 06 12:21:41 volumio volumio[11971]: info: Sending Spotify command with payload to local API: /player/volume
Dec 06 12:21:42 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 06 12:21:42 volumio volumio[11971]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5
Dec 06 12:21:42 volumio volumio[11971]: info: CoreCommandRouter::volumioGetState
Dec 06 12:21:42 volumio volumio[11971]: info: CorePlayQueue::getTrack 0
Dec 06 12:21:43 volumio volumio[11971]: info: Setting Geolocation for MyVolumio to eu2
Dec 06 12:21:43 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:43 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:43 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:44 volumio volumio[11971]: info: Updating MyVolumio device info
Dec 06 12:21:44 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:44 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:44 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:47 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:47 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:47 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Dec 06 12:21:47 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 06 12:21:47 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Dec 06 12:21:47 volumio volumio[11971]: info: CoreCommandRouter::volumioGetBrowseSources
Dec 06 12:21:47 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 06 12:21:48 volumio volumio[11971]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Dec 06 12:21:48 volumio volumio[11971]: info: Completed starting MyVolumio Plugin
Dec 06 12:21:48 volumio volumio[11971]:  [Metrics]  CommandRouter:  53s 814.93ms 
Dec 06 12:21:48 volumio volumio[11971]: info: CoreCommandRouter::volumiosetStartupVolume
Dec 06 12:21:48 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:21:48 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:21:48 volumio volumio[11971]: info: CoreCommandRouter::Close All Modals sent
Dec 06 12:21:48 volumio volumio[11971]: info: CoreCommandRouter::Close All Modals sent
Dec 06 12:21:49 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Dec 06 12:21:49 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Dec 06 12:21:49 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Dec 06 12:21:49 volumio volumio[11971]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 06 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 06 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-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 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-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 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-06:00" level=info msg="zeroconf server listening on port 38553"
Dec 06 12:21:49 volumio volumio[11971]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 06 12:21:49 volumio volumio[11971]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"ANNOUNCEMENT
\n\nProduction line
\n
\nFIX
\n\nNodejs 20.5.1 version pinning with static package fallback
\n\n","title":"Update v4.073","updateavailable":true}
Dec 06 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-06:00" level=debug msg="obtained new client token: AADXsxi81V5a5NIyeG21Sqz457HN09AW3mpyXiU1hZAo0v+VD47BcPuUrNygGIHQeDhBl7zCkmllZbJ2QlwBRY2A3biJ4KFCuhktq9RSIl7A7HkVBNRRdQHObgh+hfXq2IR37312b2YwMx1oKGntd2JvX66W6Rk8RswlawCF//KRxsDJ0L1cTzMzZoio+/Fb2965IDR7cpM1R0L6jAogNWqsFLGjjVCZCKzqu6Q3QfacN4dBJRs7BrnrSQ=="
Dec 06 12:21:49 volumio volumio[11971]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 06 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-06:00" level=debug msg="completed challenge"
Dec 06 12:21:49 volumio go-librespot[12544]: time="2025-12-06T12:21:49-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 12:21:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:49 volumio volumio[11971]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up
Dec 06 12:21:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:49 volumio volumio[11971]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 06 12:21:49 volumio volumio[11971]: Error: socket hang up
Dec 06 12:21:49 volumio volumio[11971]:     at connResetException (node:internal/errors:720:14)
Dec 06 12:21:49 volumio volumio[11971]:     at Socket.socketOnEnd (node:_http_client:519:23)
Dec 06 12:21:49 volumio volumio[11971]:     at Socket.emit (node:events:526:35)
Dec 06 12:21:49 volumio volumio[11971]:     at endReadableNT (node:internal/streams/readable:1376:12)
Dec 06 12:21:49 volumio volumio[11971]:     at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 06 12:21:49 volumio volumio[11971]:   code: 'ECONNRESET',
Dec 06 12:21:49 volumio volumio[11971]:   response: undefined
Dec 06 12:21:49 volumio volumio[11971]: }
Dec 06 12:21:49 volumio volumio[11971]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 06 12:21:50 volumio sudo[12606]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 12:20'
Dec 06 12:21:50 volumio sudo[12606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:50 volumio sudo[12606]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:51 volumio volumio-remote-updater[2353]: [2025-12-06 12:21:51] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 06 12:21:51 volumio volumio-remote-updater[2353]: [2025-12-06 12:21:51] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 06 12:21:51 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:51 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 06 12:21:51 volumio systemd[1]: volumio.service: Consumed 49.770s CPU time.
Dec 06 12:21:51 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 06 12:21:51 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 06 12:21:51 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 20978.
Dec 06 12:21:51 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 06 12:21:51 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 06 12:21:51 volumio systemd[1]: volumio.service: Consumed 49.770s CPU time.
Dec 06 12:21:51 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 06 12:21:51 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 06 12:21:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8.
Dec 06 12:21:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:53 volumio go-librespot[12633]: go-librespot daemon starting...
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=debug msg="app state loaded"
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:53 volumio volumio[12618]: info: -------------------------------------------
Dec 06 12:21:53 volumio volumio[12618]: info: -----            Volumio3              ----
Dec 06 12:21:53 volumio volumio[12618]: info: -------------------------------------------
Dec 06 12:21:53 volumio volumio[12618]: info: -----          System startup          ----
Dec 06 12:21:53 volumio volumio[12618]: info: -------------------------------------------
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21: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 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21: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 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21: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 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=info msg="zeroconf server listening on port 43841"
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=debug msg="obtained new client token: AADgtmrKjG6YEEaih9ZEFmkS8H7CPNXZ09gbbjyni79MJkztTKDgOEPkapj8kw5o8UaMjjoXftKNjyJqzZRX4h7Kbhs4Wa8xURsdBuuheoLKP9hx4YlMdoJbIJphqK3OsmolTtHtzZalN6SaBecblnFzw3QoHsoIPG4Rhniz6cnwYMmC0W6W7CWCQ/ebP1zMC+AcLrWIK3byocu/iNvgudp0qK8QFacEx9+Jo8kqRg5B/3wuK5JCOScnBA=="
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21:53-06:00" level=debug msg="completed challenge"
Dec 06 12:21:53 volumio go-librespot[12640]: time="2025-12-06T12:21: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 12:21:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:53 volumio volumio[12618]: info: MYVOLUMIO Environment detected
Dec 06 12:21:54 volumio volumio[12618]: info: Plugin folders cleanup
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning into folder /volumio/app/plugins/
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category audio_interface
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category miscellanea
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category music_service
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category plugins.json
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category system_controller
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category user_interface
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning into folder /data/plugins/
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category audio_interface
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category music_service
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category system_controller
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category system_hardware
Dec 06 12:21:54 volumio volumio[12618]: info: Scanning category user_interface
Dec 06 12:21:54 volumio volumio[12618]: info: Plugin folders cleanup completed
Dec 06 12:21:54 volumio volumio[12618]: info: -------------------------------------------
Dec 06 12:21:54 volumio volumio[12618]: info: -----      Core plugins startup        ----
Dec 06 12:21:54 volumio volumio[12618]: info: -------------------------------------------
Dec 06 12:21:54 volumio volumio[12618]: info: Loading plugins from folder /volumio/app/plugins/
Dec 06 12:21:54 volumio volumio[12618]: info: Adding plugin upnp to MyMusic Plugins
Dec 06 12:21:54 volumio volumio[12618]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 06 12:21:54 volumio volumio[12618]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 06 12:21:54 volumio volumio[12618]: info: Loading plugins from folder /data/plugins/
Dec 06 12:21:54 volumio volumio[12618]: info: Loading plugin "system"...
Dec 06 12:21:54 volumio volumio[12618]: info: Loading plugin "appearance"...
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "network"...
Dec 06 12:21:55 volumio volumio[12618]: info: Refreshing Cached IP Addresses
Dec 06 12:21:55 volumio sudo[12654]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 06 12:21:55 volumio sudo[12654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:55 volumio sudo[12656]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "services"...
Dec 06 12:21:55 volumio sudo[12654]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:55 volumio sudo[12656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "alsa_controller"...
Dec 06 12:21:55 volumio sudo[12664]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 06 12:21:55 volumio sudo[12664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:55 volumio sudo[12656]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:55 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "wizard"...
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "networkfs"...
Dec 06 12:21:55 volumio volumio[12618]: info: Starting Udev Watcher for removable devices
Dec 06 12:21:55 volumio volumio[12618]: info: Ignoring mount for partition: boot
Dec 06 12:21:55 volumio volumio[12618]: info: Ignoring mount for partition: volumio
Dec 06 12:21:55 volumio volumio[12618]: info: Ignoring mount for partition: volumio_data
Dec 06 12:21:55 volumio volumio[12618]: info: Mounting Device Wikipedia
Dec 06 12:21:55 volumio sudo[12693]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 06 12:21:55 volumio sudo[12693]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:21:55 volumio sudo[12693]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:55 volumio volumio[12618]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 06 12:21:55 volumio volumio[12618]:        dmesg(1) may have more information after failed mount system call.
Dec 06 12:21:55 volumio volumio[12618]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 06 12:21:55 volumio volumio[12618]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 06 12:21:55 volumio volumio[12618]:        dmesg(1) may have more information after failed mount system call.
Dec 06 12:21:55 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "volumio_command_line_client"...
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "upnp"...
Dec 06 12:21:55 volumio volumio[12618]: info: [1765045315476] Starting Upmpd Daemon
Dec 06 12:21:55 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "my_music"...
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "mpd"...
Dec 06 12:21:55 volumio volumio[12618]: info: Loading plugin "upnp_browser"...
Dec 06 12:21:55 volumio sudo[12664]: pam_unix(sudo:session): session closed for user root
Dec 06 12:21:56 volumio volumio-remote-updater[2353]: [2025-12-06 12:21:56] [connect] Successful connection
Dec 06 12:21:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9.
Dec 06 12:21:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:21:56 volumio go-librespot[12695]: go-librespot daemon starting...
Dec 06 12:21:56 volumio go-librespot[12696]: time="2025-12-06T12:21:56-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:21:56 volumio go-librespot[12696]: time="2025-12-06T12:21:56-06:00" level=debug msg="app state loaded"
Dec 06 12:21:56 volumio go-librespot[12696]: time="2025-12-06T12:21:56-06:00" level=debug msg="stored credentials not found"
Dec 06 12:21:56 volumio go-librespot[12696]: time="2025-12-06T12:21:56-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 06 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21:57-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 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21:57-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 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21:57-06:00" level=info msg="zeroconf server listening on port 37787"
Dec 06 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21:57-06:00" level=debug msg="obtained new client token: AACZ31YvbdIJQ+3+gct+qpzOFNP1NxzgQ9/fsKNuv9XBIRCQ6Wc7Rgc0XtZoprSSnsdSOwpY140rAnIu/2n6g+tZPo1g/zgVz/9idYewOS/R0VI1AFopqv+esUf8+gIyZLy3TpbxreNHMrDxk3XgyLdAPBLnfjCSEMukpuuArxExPe4wEC7BlhGA7w3wJn6lNNBrIIJcPX5L65Awhf2SZBZnEHbT6ufe2WYAmQ2EWIxcTkEXfW8+qak="
Dec 06 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21:57-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21:57-06:00" level=debug msg="completed keyexchange"
Dec 06 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21:57-06:00" level=debug msg="completed challenge"
Dec 06 12:21:57 volumio go-librespot[12696]: time="2025-12-06T12:21: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 12:21:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:21:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:21:57 volumio volumio[12618]: info: Loading plugin "alarm-clock"...
Dec 06 12:21:57 volumio volumio[12618]: info: Loading plugin "airplay_emulation"...
Dec 06 12:21:57 volumio volumio[12618]: info: Starting Shairport Sync
Dec 06 12:21:57 volumio volumio[12618]: info: Loading plugin "last_100"...
Dec 06 12:21:57 volumio volumio[12618]: info: Loading plugin "webradio"...
Dec 06 12:21:57 volumio volumio[12618]: info: Loading plugin "i2s_dacs"...
Dec 06 12:21:57 volumio volumio[12618]: info: I2S DAC not set, start Auto-detection
Dec 06 12:21:57 volumio volumio[12618]: info: Loading plugin "volumiodiscovery"...
Dec 06 12:21:57 volumio volumio[12618]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 06 12:21:57 volumio volumio[12618]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 06 12:21:57 volumio volumio[12618]: *** WARNING *** For more information see 
Dec 06 12:21:57 volumio volumio[12618]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 06 12:21:57 volumio volumio[12618]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 06 12:21:57 volumio volumio[12618]: *** WARNING *** For more information see 
Dec 06 12:21:57 volumio node[12618]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 06 12:21:57 volumio node[12618]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 06 12:21:57 volumio node[12618]: *** WARNING *** For more information see 
Dec 06 12:21:57 volumio node[12618]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 06 12:21:57 volumio node[12618]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 06 12:21:57 volumio node[12618]: *** WARNING *** For more information see 
Dec 06 12:21:57 volumio volumio[12618]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 06 12:21:57 volumio volumio[12618]: info: Discovery: Started advertising with name: Volumio
Dec 06 12:21:57 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 06 12:21:57 volumio volumio[12618]: info: Loading plugin "bandcamp"...
Dec 06 12:21:58 volumio volumio[12618]: info: Plugin calmradio is not enabled
Dec 06 12:21:58 volumio volumio[12618]: info: Loading plugin "soundcloud"...
Dec 06 12:21:59 volumio volumio[12618]: info: Loading plugin "spop"...
Dec 06 12:22:00 volumio volumio[12618]: info: Loading plugin "squeezelite_mc"...
Dec 06 12:22:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10.
Dec 06 12:22:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:00 volumio go-librespot[12709]: go-librespot daemon starting...
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=debug msg="app state loaded"
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-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 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-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 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-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 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=info msg="zeroconf server listening on port 45895"
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=debug msg="obtained new client token: AABB9rz6a0shP+a4VlbBFtehVYeIHn0aT/NucQ8oSrBP6dy0iaQ3fQptII+xxlf8fGBVuGWGO+vl75Li0TTQ7wRBMdW2J/m0nIrhv7kZ1YdvcsvNyK5/41ac1avbyI4duIw1XRle8SiIgSF/pyvcwYbXXHJdar8rbQw4uwAXmmNj30KpjghBRIAr0binoCCasMIF+wAOViFH2HKAwrhrtvWuTwbCl4/5UD8/au+ThU4EUcRyuG1GZWPZLA=="
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:22:00 volumio volumio[12618]: info: Loading plugin "youtube2"...
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:00 volumio go-librespot[12710]: time="2025-12-06T12:22:00-06:00" level=debug msg="completed challenge"
Dec 06 12:22:01 volumio go-librespot[12710]: time="2025-12-06T12:22: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 12:22:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:01 volumio volumio[12618]: info: Loading plugin "ytcr"...
Dec 06 12:22:02 volumio volumio[12618]: info: Loading plugin "ytmusic"...
Dec 06 12:22:03 volumio volumio[12618]: info: Plugin now_playing is not enabled
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "outputs"...
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "albumart"...
Dec 06 12:22:03 volumio volumio[12618]: info: Plugin example_plugin is not enabled
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "inputs"...
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "updater_comm"...
Dec 06 12:22:03 volumio volumio[12618]: info: Plugin mpdemulation is not enabled
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "rest_api"...
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "websocket"...
Dec 06 12:22:03 volumio volumio[12618]: info: Starting Socket.io Server version 1.7.4
Dec 06 12:22:03 volumio volumio[12618]: info: Plugin fusiondsp is not enabled
Dec 06 12:22:03 volumio volumio[12618]: info: Plugin mpdoutput is not enabled
Dec 06 12:22:03 volumio volumio[12618]: info: Plugin RoonBridge is not enabled
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "podcast"...
Dec 06 12:22:03 volumio volumio[12618]: info: ControllerPodcast::constructor
Dec 06 12:22:03 volumio volumio[12618]: info: Loading plugin "volusonic"...
Dec 06 12:22:04 volumio volumio[12718]: Forking 3 albumart workers
Dec 06 12:22:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11.
Dec 06 12:22:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:04 volumio go-librespot[12755]: go-librespot daemon starting...
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=debug msg="app state loaded"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22: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 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22: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 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22: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 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=info msg="zeroconf server listening on port 33923"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=debug msg="obtained new client token: AABOMWQFjg3bPJy4zGTmWAsUk1y5xXsRJn9YgRGCDMnHG7HWLN4XYrmC9PF3Rvbujzujt13BsMDH5YVt+zrrqy57kGtlZ1mjLId9N6GoQ7Y5+0tW9FujNPTMplCZhDHDwuj6GtTwIWITn+dqunAs5ySm9M12zIxE3OCuvZdUqwvt+BC9eGMcfjHCzR+nApAcFpUCMemC+92ZUaYZPSVvheNzkdMksoZkpyDwjZ1lt6JWHOErhaReVaaH5g=="
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22:04-06:00" level=debug msg="completed challenge"
Dec 06 12:22:04 volumio go-librespot[12758]: time="2025-12-06T12:22: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 12:22:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:05 volumio volumio[12618]: info: Applying required configuration parameters for plugin volusonic
Dec 06 12:22:05 volumio volumio[12618]: info: Loading plugin "backup_restore"...
Dec 06 12:22:05 volumio volumio[12730]: Starting albumart workers
Dec 06 12:22:05 volumio volumio[12728]: Starting albumart workers
Dec 06 12:22:05 volumio volumio[12729]: Starting albumart workers
Dec 06 12:22:06 volumio volumio[12618]: info: Applying required configuration parameters for plugin backup_restore
Dec 06 12:22:06 volumio volumio[12618]: info: Plugin rpi_eeprom_config is not enabled
Dec 06 12:22:06 volumio volumio[12618]: info: Plugin rpi_eeprom_updater is not enabled
Dec 06 12:22:06 volumio volumio[12618]: info: Loading plugin "scheduledrestart"...
Dec 06 12:22:06 volumio volumio[12618]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 06 12:22:06 volumio volumio[12618]: info: Plugin Bluetoothremote is not enabled
Dec 06 12:22:06 volumio volumio[12618]: info: Plugin music_services_shield is not enabled
Dec 06 12:22:06 volumio volumio[12618]: info: Loading plugin "Systeminfo"...
Dec 06 12:22:06 volumio volumio[12618]: info: Plugin peppymeterbasic is not enabled
Dec 06 12:22:06 volumio volumio[12618]: info: Loading plugin "peppyspectrum"...
Dec 06 12:22:07 volumio volumio[12618]: info: Loading i18n strings for locale en
Dec 06 12:22:07 volumio volumio[12618]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 06 12:22:07 volumio volumio[12618]: Updating browse sources language
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::initPlayerControls
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: Express server listening on port 3000
Dec 06 12:22:07 volumio volumio[12618]:  [Metrics]  WebUI:  14s 601.33ms 
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::resetVolumioState
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::getcurrentVolume
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioRetrievevolume
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:07 volumio sudo[12803]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 06 12:22:07 volumio sudo[12803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:07 volumio sudo[12805]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 06 12:22:07 volumio sudo[12805]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:07 volumio sudo[12803]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:07 volumio sudo[12805]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:07 volumio volumio[12618]: info: Volumio Network Manager: Network status updated: 1
Dec 06 12:22:07 volumio volumio[12618]: info: VolumeController:: Volume=86 Mute =false
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::pushState
Dec 06 12:22:07 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioPushState
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::updateTrackBlock
Dec 06 12:22:07 volumio volumio[12618]: info: CorePlayQueue::getTrackBlock
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioRetrievevolume
Dec 06 12:22:07 volumio volumio[12618]: info: Reloading queue from file
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::setRepeat null single undefined
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::pushState
Dec 06 12:22:07 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioPushState
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::setRandom null
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::pushState
Dec 06 12:22:07 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioPushState
Dec 06 12:22:07 volumio volumio[12618]: info: Setting Device type: Raspberry PI
Dec 06 12:22:07 volumio volumio[12618]: info: VolumeController:: Volume=86 Mute =false
Dec 06 12:22:07 volumio volumio[12618]: info: CoreStateMachine::pushState
Dec 06 12:22:07 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioPushState
Dec 06 12:22:07 volumio volumio[12618]: info: Completed loading Core Plugins
Dec 06 12:22:07 volumio sudo[12819]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 06 12:22:07 volumio sudo[12819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:07 volumio volumio[12618]: info: Preparing to generate the ALSA configuration file
Dec 06 12:22:07 volumio volumio[12618]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 06 12:22:07 volumio volumio[12618]: info: Discovery: Found device Volumio
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioGetState
Dec 06 12:22:07 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:07 volumio volumio[12618]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 06 12:22:07 volumio volumio[12618]: info: Reading ALSA contributions from plugins.
Dec 06 12:22:07 volumio sudo[12819]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:07 volumio volumio[12618]: info: Discovery: this is already registered,  a135e40e-a404-457b-98f5-36bf71c75954
Dec 06 12:22:07 volumio volumio[12618]: info: Discovery: Found device Volumio
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioGetState
Dec 06 12:22:07 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:07 volumio volumio[12618]: info: Upmpdcli Daemon Started
Dec 06 12:22:07 volumio volumio[12618]: info: Asound.conf file unchanged, so no further update is needed
Dec 06 12:22:07 volumio volumio[12618]: info: Output device has changed, restarting MPD
Dec 06 12:22:07 volumio volumio[12618]: info: Output device has changed, restarting Shairport Sync
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:07 volumio sudo[12822]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 06 12:22:07 volumio sudo[12822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:07 volumio sudo[12822]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:07 volumio sudo[12824]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 06 12:22:07 volumio sudo[12824]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:07 volumio volumio[12618]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:22:07 volumio volumio[12618]: info: ___________ START PLUGINS ___________
Dec 06 12:22:07 volumio volumio[12618]: info: ControllerMpd::onStart: Initializing MPD
Dec 06 12:22:07 volumio volumio[12618]: info: Creating MPD Configuration file
Dec 06 12:22:07 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:22:07 volumio sudo[12832]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 06 12:22:07 volumio sudo[12832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:07 volumio sudo[12834]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 06 12:22:07 volumio sudo[12834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:07 volumio volumio[12618]: info: [1765045327828] CoreMusicLibrary::Adding element Media Servers
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:07 volumio sudo[12832]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:07 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 06 12:22:07 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 06 12:22:07 volumio systemd[1]: mpd.service: Consumed 4.576s CPU time.
Dec 06 12:22:07 volumio volumio[12618]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:22:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12.
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:07 volumio volumio[12618]: info: [1765045327932] CoreMusicLibrary::Adding element Last_100
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:07 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:07 volumio volumio[12618]: info: [1765045327937] CoreMusicLibrary::Adding element Webradio
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:07 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 06 12:22:07 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 06 12:22:07 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 06 12:22:07 volumio volumio[12618]: info: Initializing BBC Radios
Dec 06 12:22:07 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 06 12:22:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:08 volumio go-librespot[12854]: go-librespot daemon starting...
Dec 06 12:22:08 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=debug msg="app state loaded"
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:08 volumio volumio[12618]: info: [1765045328043] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:08 volumio volumio[12618]: info: [1765045328054] CoreMusicLibrary::Adding element SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: info: Creating Spotify config file
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:08 volumio sudo[12865]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 06 12:22:08 volumio sudo[12865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 06 12:22:08 volumio sudo[12865]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-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 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-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 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=info msg="zeroconf server listening on port 40739"
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=debug msg="obtained new client token: AACQEKTq8BngcZC+L96FEYgna7ArZWconBw1A8fw40ramLnA+EW3NNJd1/taFbYelxBsQbR3c9UVKxqSd4Ip2jgReNs6HPYoClxvCBTzV7wvaiNoLv6C4tOx58pAffy+yMmgtfw4A3OXKHwwahlXxvnYW7lEfq5M0/saystYkZZ1fnpRgr42DTdfDmCyZYtntTeSdmqdJNpBIA4uuNnOBkgedRwffuwjd5k9eRFqXMKQuz0SCLgzWPageA=="
Dec 06 12:22:08 volumio volumio[12618]: info: [squeezelite_mc] Starting proxy server...
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:08 volumio volumio[12618]: info: [1765045328444] CoreMusicLibrary::Adding element YouTube2
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube2
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:08 volumio volumio[12618]: info: [1765045328463] CoreMusicLibrary::Adding element YouTube Music
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube2
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube Music
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:08 volumio volumio[12618]: info: [1765045328477] CoreMusicLibrary::Adding element Podcast
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube2
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube Music
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Podcast
Dec 06 12:22:08 volumio volumio[12618]: info: Loading i18n strings for locale en
Dec 06 12:22:08 volumio volumio[12618]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 06 12:22:08 volumio volumio[12618]: Updating browse sources language
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube2
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube Music
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Podcast
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube2
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube Music
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Podcast
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:08 volumio volumio[12618]: info: [1765045328525] CoreMusicLibrary::Adding element Volusonic
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:08 volumio volumio-remote-updater[2353]: [2025-12-06 12:22:08] [connect] Successful connection
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube2
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source YouTube Music
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Podcast
Dec 06 12:22:08 volumio volumio[12618]: Cannot find translation for source Volusonic
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22:08-06:00" level=debug msg="completed challenge"
Dec 06 12:22:08 volumio volumio[12618]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 06 12:22:08 volumio go-librespot[12856]: time="2025-12-06T12:22: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 12:22:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 06 12:22:08 volumio volumio[12618]: info: Volumio Calling Home
Dec 06 12:22:08 volumio volumio[12618]: info: [squeezelite_mc] Proxy server started on port 34503
Dec 06 12:22:08 volumio volumio[12618]: info: Preparing to generate the ALSA configuration file
Dec 06 12:22:08 volumio volumio[12618]: info: CoreCommandRouter::volumioRetrievevolume
Dec 06 12:22:08 volumio volumio[12618]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 06 12:22:08 volumio volumio[12618]: info: Reading ALSA contributions from plugins.
Dec 06 12:22:08 volumio volumio[12618]: info: MPD Permissions set
Dec 06 12:22:08 volumio volumio[12618]: info: MPD Permissions set
Dec 06 12:22:08 volumio volumio-remote-updater[2353]: [2025-12-06 12:22:08] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765045328 101
Dec 06 12:22:08 volumio volumio[12618]: 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 12:22:08 volumio volumio[12618]: info: Spotify config file written
Dec 06 12:22:08 volumio sudo[12876]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 06 12:22:08 volumio sudo[12876]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:08 volumio volumio[12618]: 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 12:22:09 volumio volumio[12618]: info: VolumeController:: Volume=86 Mute =false
Dec 06 12:22:09 volumio volumio[12618]: info: CoreStateMachine::pushState
Dec 06 12:22:09 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::volumioPushState
Dec 06 12:22:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:09 volumio go-librespot[12878]: go-librespot daemon starting...
Dec 06 12:22:09 volumio volumio[12618]: info: [squeezelite_mc] Server discovery started
Dec 06 12:22:09 volumio volumio[12618]: info: [squeezelite_mc] Player finder started
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:22:09 volumio sudo[12876]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:09 volumio volumio[12618]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero  2>&1 || true
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=debug msg="app state loaded"
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio volumio[12618]: info: No need to fix Spotify hosts
Dec 06 12:22:09 volumio volumio[12618]: 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 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-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 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-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 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-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 12:22:09 volumio volumio[12618]: info: Volumio called home
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=info msg="zeroconf server listening on port 43129"
Dec 06 12:22:09 volumio volumio[12618]: 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 12:22:09 volumio volumio[12618]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 06 12:22:09 volumio volumio[12618]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 06 12:22:09 volumio volumio[12618]: 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 12:22:09 volumio volumio[12618]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 06 12:22:09 volumio volumio[12618]: SPOTIFY: BQCUxBBfUoioD5BVEYs2iQWTPFg_W47F5uelLPba5EW5kAbfWDvMS00fHhwayWljKLyQZP7MKloEvkAV6ymd5_S4eguLUraV7NhCxdzX-01GHaEx_EmjJVm6bior6lJZlMjotItC-BgNsN9MZdleIT14zIf67xmEQt2XroUGMslGDEB5Fmc0NjEbT52QCCqTiX4_kshkJR3hG_-3mb_T0Gia8HZEkIrl1yUA9uU
Dec 06 12:22:09 volumio volumio[12618]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 06 12:22:09 volumio volumio[12618]: info: New Spotify access token = BQCUxBBfUoioD5BVEYs2iQWTPFg_W47F5uelLPba5EW5kAbfWDvMS00fHhwayWljKLyQZP7MKloEvkAV6ymd5_S4eguLUraV7NhCxdzX-01GHaEx_EmjJVm6bior6lJZlMjotItC-BgNsN9MZdleIT14zIf67xmEQt2XroUGMslGDEB5Fmc0NjEbT52QCCqTiX4_kshkJR3hG_-3mb_T0Gia8HZEkIrl1yUA9uU
Dec 06 12:22:09 volumio volumio[12618]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=debug msg="obtained new client token: AABh4Z4iXQjs7oPFmJyvDXjbzO7asSr+2oBSjYjYLKRP1T1WlUPHGoo8IlyNLmXx5Ha8CAIbpJ6F5xH+LzH9dukTlUVfVhWICmouSjXBMnHr0YAQUtyL5x91EIN5R0J0q0gFifDa8cyG5wwri/iIAJK4ts51sSGJVsM6n5h/nRb/CZBmRKCxj3YuOYBeb+5WzOvoEzAX8eTuBPhjOabgNmdXlR4JdLu2UNi4FH46WLVTvEvSGIwvI4q09A=="
Dec 06 12:22:09 volumio volumio[12618]: info: Starting Shairport Sync
Dec 06 12:22:09 volumio volumio[12618]: info: Starting Shairport Sync
Dec 06 12:22:09 volumio volumio[12618]: info: Starting Shairport Sync
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:22:09 volumio sudo[12903]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:22:09 volumio sudo[12903]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:09 volumio sudo[12906]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:22:09 volumio sudo[12906]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-06:00" level=debug msg="completed challenge"
Dec 06 12:22:09 volumio sudo[12908]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:22:09 volumio sudo[12908]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:09 volumio sudo[12900]:  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 12:22:09 volumio sudo[12900]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:09 volumio go-librespot[12879]: time="2025-12-06T12:22:09-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 12:22:09 volumio sudo[12900]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:09 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 06 12:22:09 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 06 12:22:09 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:22:09 volumio systemd[1]: shairport-sync.service: Consumed 2.093s CPU time.
Dec 06 12:22:09 volumio volumio[12618]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 06 12:22:09 volumio volumio[12618]: info: Asound.conf file unchanged, so no further update is needed
Dec 06 12:22:09 volumio volumio[12618]: info: Output device has changed, restarting MPD
Dec 06 12:22:09 volumio sudo[12916]:  volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 06 12:22:09 volumio volumio[12618]: info: Output device has changed, restarting Shairport Sync
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:09 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:22:09 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:09 volumio sudo[12916]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:09 volumio sudo[12906]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:09 volumio sudo[12916]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:09 volumio sudo[12903]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:09 volumio sudo[12908]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:09 volumio volumio[12618]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 06 12:22:09 volumio sudo[12918]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 06 12:22:09 volumio sudo[12920]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 06 12:22:09 volumio sudo[12920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:09 volumio sudo[12918]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:09 volumio sudo[12918]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:09 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 06 12:22:09 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 06 12:22:09 volumio systemd[1]: mpd.service: Consumed 1.720s CPU time.
Dec 06 12:22:09 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 06 12:22:09 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 06 12:22:09 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 06 12:22:10 volumio volumio[12618]: info: MPD Permissions set
Dec 06 12:22:10 volumio volumio[12618]: info: Shairport-Sync Started
Dec 06 12:22:10 volumio volumio[12618]: Error adding Membership: Error: addMembership EINVAL
Dec 06 12:22:10 volumio volumio[12618]: info: Shairport-Sync Started
Dec 06 12:22:10 volumio volumio[12618]: 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 12:22:10 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 06 12:22:10 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 06 12:22:10 volumio volumio[12618]: info: Shairport-Sync Started
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:10 volumio sudo[12950]:  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 12:22:10 volumio sudo[12950]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::volumioGetState
Dec 06 12:22:10 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:10 volumio sudo[12950]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:10 volumio volumio[12618]: info: Starting Shairport Sync
Dec 06 12:22:10 volumio sudo[12958]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 06 12:22:10 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload  || true
Dec 06 12:22:10 volumio sudo[12958]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:10 volumio sudo[12948]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 06 12:22:10 volumio sudo[12948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 06 12:22:10 volumio sudo[12948]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:10 volumio volumio[12618]: 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 12:22:10 volumio volumio[12618]: info: Spotify Successfully logged in
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 06 12:22:10 volumio volumio[12618]: info: [1765045330357] CoreMusicLibrary::Adding element Spotify
Dec 06 12:22:10 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 06 12:22:10 volumio volumio[12618]: Cannot find translation for source Bandcamp Discover
Dec 06 12:22:10 volumio volumio[12618]: Cannot find translation for source SoundCloud
Dec 06 12:22:10 volumio volumio[12618]: Cannot find translation for source YouTube2
Dec 06 12:22:10 volumio volumio[12618]: Cannot find translation for source YouTube Music
Dec 06 12:22:10 volumio volumio[12618]: Cannot find translation for source Podcast
Dec 06 12:22:10 volumio volumio[12618]: Cannot find translation for source Volusonic
Dec 06 12:22:10 volumio volumio[12618]: Cannot find translation for source Spotify
Dec 06 12:22:10 volumio sudo[12962]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 06 12:22:10 volumio sudo[12962]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:10 volumio systemd[1]: Reloading.
Dec 06 12:22:10 volumio volumio[12618]: info: [squeezelite_mc] Notification listener started
Dec 06 12:22:10 volumio volumio[12618]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 06 12:22:11 volumio volumio[12618]: 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 12:22:11 volumio volumio[12618]: 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 12:22:11 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:11 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:11 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 06 12:22:11 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 06 12:22:12 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 12:22:12 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 12:22:12 volumio volumio[12618]: info: go-librespot daemon successfully initialized
Dec 06 12:22:12 volumio volumio[12618]: info: CoreCommandRouter::volumioGetState
Dec 06 12:22:12 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:12 volumio sudo[12962]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:12 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:22:12 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 06 12:22:12 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 06 12:22:12 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:22:12 volumio systemd[1]: shairport-sync.service: Consumed 1.489s CPU time.
Dec 06 12:22:12 volumio sudo[12984]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:22:12 volumio sudo[12984]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:12 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 06 12:22:12 volumio sudo[12958]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:12 volumio volumio[12618]: info: Shairport-Sync Started
Dec 06 12:22:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13.
Dec 06 12:22:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:12 volumio go-librespot[12986]: go-librespot daemon starting...
Dec 06 12:22:12 volumio go-librespot[12987]: time="2025-12-06T12:22:12-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:12 volumio go-librespot[12987]: time="2025-12-06T12:22:12-06:00" level=debug msg="app state loaded"
Dec 06 12:22:12 volumio go-librespot[12987]: time="2025-12-06T12:22:12-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:12 volumio go-librespot[12987]: time="2025-12-06T12:22:12-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:12 volumio sudo[12984]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:12 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 06 12:22:12 volumio sudo[13008]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 06 12:22:12 volumio sudo[13008]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:12 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 06 12:22:13 volumio volumio[12618]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 06 12:22:13 volumio volumio[12618]: info: CoreCommandRouter::volumioGetState
Dec 06 12:22:13 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-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 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-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 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-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 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-06:00" level=info msg="zeroconf server listening on port 40715"
Dec 06 12:22:13 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 06 12:22:13 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 06 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-06:00" level=debug msg="obtained new client token: AADJPsgvnO0EinEOWpcgmUvFFROYIbAUD8ka9PbsHHa1w85bPejqvVovrUb7s5o5iCeCgHQyT5fiHx1lIwphf+E0mr9rRiblqBHg4ceM+GF9RAiDeqS45jqBXK/rTAuNF3tiEmVAblmOMPaxErGA9HJ3ntJ4+xvJKeAK5qeHIIB1+SXE4h0xtv+1yXwAcIhXTM5uHzr7YhnLD36jqg7uptDj9y8iw91kzGhQ7Ijhdliz5mHUQrTj8oU="
Dec 06 12:22:13 volumio sudo[13008]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-06:00" level=debug msg="completed challenge"
Dec 06 12:22:13 volumio go-librespot[12987]: time="2025-12-06T12:22:13-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 12:22:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:13 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:22:13 volumio sudo[13012]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:22:13 volumio sudo[13012]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:13 volumio sudo[13012]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:13 volumio volumio[12618]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 06 12:22:13 volumio sudo[13016]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 06 12:22:13 volumio sudo[13016]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:13 volumio sudo[13016]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:13 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 06 12:22:13 volumio sudo[13019]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 06 12:22:13 volumio sudo[13019]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:14 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 06 12:22:14 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 06 12:22:14 volumio sudo[13019]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:14 volumio volumio[12618]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 06 12:22:14 volumio volumio[12618]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 06 12:22:14 volumio volumio[12618]: 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 12:22:14 volumio volumio[12618]: 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 12:22:14 volumio mpd[12963]: 2025-12-06T12:22:14 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 06 12:22:14 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 06 12:22:14 volumio sudo[12920]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:14 volumio sudo[12824]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:14 volumio sudo[12834]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:14 volumio volumio[12618]: error: MPD error: The expression evaluated to a falsy value:
Dec 06 12:22:14 volumio volumio[12618]:   assert.ok(self.idling)
Dec 06 12:22:14 volumio volumio[12618]: error: The expression evaluated to a falsy value:
Dec 06 12:22:14 volumio volumio[12618]:   assert.ok(self.idling)
Dec 06 12:22:14 volumio volumio[12618]: error: MPD error: The expression evaluated to a falsy value:
Dec 06 12:22:14 volumio volumio[12618]:   assert.ok(self.idling)
Dec 06 12:22:14 volumio volumio[12618]: error: The expression evaluated to a falsy value:
Dec 06 12:22:14 volumio volumio[12618]:   assert.ok(self.idling)
Dec 06 12:22:14 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:22:14 volumio volumio[12618]: info: MPD running with PID12963
Dec 06 12:22:14 volumio volumio[12618]:  ,establishing connection
Dec 06 12:22:14 volumio volumio[12618]: error: updateQueue error: null
Dec 06 12:22:14 volumio volumio[12618]: error: updateQueue error: null
Dec 06 12:22:14 volumio sudo[13030]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:22:14 volumio sudo[13030]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:14 volumio sudo[13030]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:15 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:22:15 volumio sudo[13033]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:22:15 volumio sudo[13033]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:15 volumio sudo[13033]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:15 volumio volumio[12618]: info: CoreCommandRouter::volumioGetState
Dec 06 12:22:15 volumio volumio[12618]: info: CorePlayQueue::getTrack 0
Dec 06 12:22:15 volumio volumio[12618]: info: Initializing connection to go-librespot Websocket
Dec 06 12:22:15 volumio volumio[12618]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:22:15 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:22:15 volumio sudo[13050]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:22:15 volumio sudo[13050]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:15 volumio sudo[13050]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:16 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:22:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14.
Dec 06 12:22:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:16 volumio sudo[13053]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:22:16 volumio sudo[13053]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:16 volumio go-librespot[13054]: go-librespot daemon starting...
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=debug msg="app state loaded"
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:16 volumio sudo[13053]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-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 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-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 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-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 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=info msg="zeroconf server listening on port 43663"
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=debug msg="obtained new client token: AABKbMSWOKMuWULuT+S3OC9YD6EL7x3iDsJ2TwHVEjfFkK2SY9uCrKQxIfjcOIxLABUciOq/Yok25GfWIpmEy3Tz5eBZ7inxCszSatmeTbWjeFwxW5jOZgnS6UZQFgo4WpaZMitCawfORAuiWYYUsLxUzzn88R+k05k6YEUb1CvmlgOUPu0+0xcN1txc9rEBqkvkg5ZFaSC22rs049XHWEseit6/lqxVLuObw41ExQL+y7MdKXWwUNqmOA=="
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:16 volumio go-librespot[13056]: time="2025-12-06T12:22:16-06:00" level=debug msg="completed challenge"
Dec 06 12:22:17 volumio go-librespot[13056]: time="2025-12-06T12:22:17-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 12:22:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:17 volumio volumio[12618]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 06 12:22:17 volumio sudo[13064]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 06 12:22:17 volumio sudo[13064]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:17 volumio sudo[13064]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:17 volumio volumio[12618]: info: Completed starting Core Plugins
Dec 06 12:22:17 volumio volumio[12618]: info: -------------------------------------------
Dec 06 12:22:17 volumio volumio[12618]: info: -----    MyVolumio plugins startup     ----
Dec 06 12:22:17 volumio volumio[12618]: info: -------------------------------------------
Dec 06 12:22:17 volumio volumio[12618]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 06 12:22:17 volumio sudo[13067]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 06 12:22:17 volumio sudo[13067]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:17 volumio sudo[13069]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 06 12:22:17 volumio sudo[13069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:17 volumio sudo[13071]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 06 12:22:17 volumio sudo[13071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:17 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 06 12:22:17 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 06 12:22:17 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 06 12:22:17 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 06 12:22:17 volumio sudo[13071]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:17 volumio sudo[13067]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:17 volumio mpd_monitor.sh[13075]: MPD Monitor Service: Starting MPD Monitor Service
Dec 06 12:22:17 volumio sudo[13069]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:17 volumio volumio[12618]: info: Successfully started MPD Monitor
Dec 06 12:22:17 volumio volumio[12618]: info: Successfully started MPD Monitor
Dec 06 12:22:17 volumio volumio[12618]: info: Successfully started MPD Monitor
Dec 06 12:22:18 volumio volumio[12618]: info: Initializing connection to go-librespot Websocket
Dec 06 12:22:18 volumio volumio[12618]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:22:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15.
Dec 06 12:22:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:20 volumio go-librespot[13080]: go-librespot daemon starting...
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=debug msg="app state loaded"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-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 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-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 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-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 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=info msg="zeroconf server listening on port 44983"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=debug msg="obtained new client token: AAB2ttAweAbXhiock7pOsMTHcubz4xg0NTwJmjenb9MjPgwzRSzEDXSXQDAPHeGLigj2600nE8a1NSoFGetJwPQYAvU6WIH/jdAR9uIlSVGnw4fT2XIWT8wmOA/nZmZhjzzs6XwWzY7zR4zfWIQpdTRpiST9DvLspAZnOCEQAe6laV0A89Xd/qsrpeR1P/DQiYGHjqn9m1insTahD07V+H7co3SFVECp/CSd1deytZVUI1cEuKe5CFS/Ww=="
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-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 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:443, retrying with a different AP" error="dial tcp 104.154.127.247:443: connect: connection refused"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=debug msg="connected to ap-guc3.spotify.com:80"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22:20-06:00" level=debug msg="completed challenge"
Dec 06 12:22:20 volumio go-librespot[13081]: time="2025-12-06T12:22: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 12:22:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:22 volumio volumio[12618]: info: Initializing connection to go-librespot Websocket
Dec 06 12:22:22 volumio volumio[12618]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:22:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16.
Dec 06 12:22:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:24 volumio go-librespot[13088]: go-librespot daemon starting...
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=debug msg="app state loaded"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-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 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-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 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-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 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=info msg="zeroconf server listening on port 34853"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=debug msg="obtained new client token: AAAggA14BdIc7ijdpyt4/oILRtlKobQOmMYYcZ+/lgDtcq8tQykhfQyLv8eGrhRYHFapv0ZWu1xswn6+unoUvzP0oe64ljHZTYJkMarXVCtdnl6FFF4bIT5Ef3ibIn+qSNGrH7HBf1UYcpKkhZxxkDlavpsBLBAOnyIibBU3EBiPPneHpN90MXggz0MkDGaajm8TdgYjkMHvqUF7xKzPIAYAsowuCIuflry7c2cufSVZRphSStpu1z0CuA=="
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-06:00" level=debug msg="completed challenge"
Dec 06 12:22:24 volumio go-librespot[13089]: time="2025-12-06T12:22:24-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 12:22:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:25 volumio volumio[12618]: info: Initializing connection to go-librespot Websocket
Dec 06 12:22:25 volumio volumio[12618]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 06 12:22:25 volumio volumio[12618]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 06 12:22:25 volumio volumio[12618]: info: Adding plugin multiroom to MyMusic Plugins
Dec 06 12:22:25 volumio volumio[12618]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 06 12:22:25 volumio volumio[12618]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 06 12:22:25 volumio volumio[12618]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 06 12:22:25 volumio volumio[12618]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 06 12:22:25 volumio volumio[12618]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 06 12:22:25 volumio volumio[12618]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 06 12:22:26 volumio volumio[12618]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 06 12:22:26 volumio volumio[12618]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 06 12:22:26 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:26 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:26 volumio volumio[12618]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 06 12:22:26 volumio volumio[12618]: info: MyVolumio login type: Token
Dec 06 12:22:26 volumio volumio[12618]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 06 12:22:26 volumio volumio[12618]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 06 12:22:27 volumio volumio[12618]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 06 12:22:27 volumio volumio[12618]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 06 12:22:27 volumio volumio[12618]: info: Streaming services startup
Dec 06 12:22:27 volumio volumio[12618]: info: Starting Streaming Daemon
Dec 06 12:22:27 volumio sudo[13111]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 06 12:22:27 volumio sudo[13111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:27 volumio volumio[12618]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 06 12:22:27 volumio sudo[13111]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:27 volumio volumio[12618]: error: Cannot start Volumio Streaming Daemon
Dec 06 12:22:27 volumio volumio[12618]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 06 12:22:27 volumio volumio[12618]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 06 12:22:27 volumio volumio[12618]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 06 12:22:28 volumio volumio[12618]: info: MyVolumio token set successfully
Dec 06 12:22:28 volumio volumio[12618]: info: MYVOLUMIO: Adding device
Dec 06 12:22:28 volumio volumio[12618]: info: MYVOLUMIO: Evaluating Server
Dec 06 12:22:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17.
Dec 06 12:22:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:28 volumio go-librespot[13128]: go-librespot daemon starting...
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=debug msg="app state loaded"
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:28 volumio volumio[12618]: info: MyVolumio status changed
Dec 06 12:22:28 volumio volumio[12618]: info: Streaming services startup
Dec 06 12:22:28 volumio volumio[12618]: info: Starting Streaming Daemon
Dec 06 12:22:28 volumio volumio[12618]: info: Removing browser output: myVolumio user plan is not superstar
Dec 06 12:22:28 volumio volumio[12618]: info: Removing audio output:
Dec 06 12:22:28 volumio volumio[12618]: info: Stoppping Tunnel 1
Dec 06 12:22:28 volumio sudo[13147]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 06 12:22:28 volumio sudo[13147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:28 volumio volumio[12618]: info: Initializing connection to go-librespot Websocket
Dec 06 12:22:28 volumio sudo[13149]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 06 12:22:28 volumio sudo[13149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=debug msg="new websocket client"
Dec 06 12:22:28 volumio volumio[12618]: info: Connection to go-librespot Websocket established
Dec 06 12:22:28 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 12:22:28 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 12:22:28 volumio sudo[13147]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:28 volumio volumio[12618]: error: Cannot start Volumio Streaming Daemon
Dec 06 12:22:28 volumio volumio[12618]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 06 12:22:28 volumio volumio[12618]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 06 12:22:28 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 12:22:28 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 12:22:28 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 12:22:28 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 12:22:28 volumio sudo[13149]: pam_unix(sudo:session): session closed for user root
Dec 06 12:22:28 volumio volumio[12618]: info: Remote SSH Stopped
Dec 06 12:22:28 volumio volumio[12618]: info: Setting Geolocation for MyVolumio to us1
Dec 06 12:22:28 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:28 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:28 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-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 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-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 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-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 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=info msg="zeroconf server listening on port 34599"
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=debug msg="obtained new client token: AABfryz7ws1ytoKQb08xqRXsAvDf5/ycFYvfNLvpSlT8aPW4Kbd/PC6Ak4GNTMLZvfgRtfA6I7m3is6DQs9rCAVT1clqIjB9vxJ+bzyIzZjig8VgK4BXwJvdw24CzMJ4/YGs07dIvgSqgnl6A/D5efCyfmc/lmLFIOLpMAUo+yJfLR4eId1uKONR3aGC02EUcKKidWcPVHkQMpXToouotfxUSHtLtVXSQz/GK69mvE7Cyj7ApNWI+bJM6A=="
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-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 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=debug msg="connected to ap-guc3.spotify.com:443"
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=debug msg="completed keyexchange"
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-06:00" level=debug msg="completed challenge"
Dec 06 12:22:28 volumio go-librespot[13135]: time="2025-12-06T12:22:28-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 12:22:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 06 12:22:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 06 12:22:28 volumio volumio[12618]: info: Connection to go-librespot Websocket closed
Dec 06 12:22:29 volumio volumio[12618]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 06 12:22:29 volumio volumio[12618]: info: Updating MyVolumio device info
Dec 06 12:22:29 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:29 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:29 volumio volumio[12618]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 06 12:22:30 volumio volumio[12618]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 06 12:22:31 volumio volumio[12618]: info: Getting Spotify volume
Dec 06 12:22:31 volumio volumio[12618]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 06 12:22:31 volumio volumio[12618]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 06 12:22:31 volumio volumio[12618]:     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 06 12:22:31 volumio volumio[12618]:   errno: -111,
Dec 06 12:22:31 volumio volumio[12618]:   code: 'ECONNREFUSED',
Dec 06 12:22:31 volumio volumio[12618]:   syscall: 'connect',
Dec 06 12:22:31 volumio volumio[12618]:   address: '127.0.0.1',
Dec 06 12:22:31 volumio volumio[12618]:   port: 9879,
Dec 06 12:22:31 volumio volumio[12618]:   response: undefined
Dec 06 12:22:31 volumio volumio[12618]: }
Dec 06 12:22:31 volumio volumio[12618]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 06 12:22:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18.
Dec 06 12:22:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 06 12:22:32 volumio go-librespot[13164]: go-librespot daemon starting...
Dec 06 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-06:00" level=info msg="running go-librespot 0.4.0"
Dec 06 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-06:00" level=debug msg="app state loaded"
Dec 06 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-06:00" level=debug msg="stored credentials not found"
Dec 06 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 06 12:22:32 volumio sudo[13174]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 12:21'
Dec 06 12:22:32 volumio sudo[13174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 06 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-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 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-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 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-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 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-06:00" level=info msg="zeroconf server listening on port 33861"
Dec 06 12:22:32 volumio go-librespot[13165]: time="2025-12-06T12:22:32-06:00" level=debug msg="obtained new client token: AAAtbVxJN7qOpSBUhnSy5mO84SbiFhZ7X9ZdFg0N6IwvMkcKxUAQSV3eQoiF5qluirZo/QHwkDh0mtKPX0vCHT83WWu6OSXTB4fVMASUxi4Xc8NOlkC+7/HUw5oqwI/nk4hkWaSZqkIDEmX3+UPgaxZnzJSZiPi2opi+kXBG2r7ieyzLT0OvulRmXbeup+lYXCe39cxvkPDWGG0TKaISt7AvdIG9kAbPxAPswKUCbNii0jMP6SAELrm0kQ=="
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"