Dec 09 02:56:00 volumio volumio[32628]: info: Discovery: this is already registered,  a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 02:56:00 volumio volumio[32628]: info: Discovery: Found device Volumio
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:00 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:00 volumio volumio[32628]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 02:56:00 volumio volumio[32628]: info: Reading ALSA contributions from plugins.
Dec 09 02:56:00 volumio volumio[32628]: info: Upmpdcli Daemon Started
Dec 09 02:56:00 volumio volumio[32628]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 02:56:00 volumio volumio[32628]: info: Output device has changed, restarting MPD
Dec 09 02:56:00 volumio volumio[32628]: info: Output device has changed, restarting Shairport Sync
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:00 volumio sudo[374]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 02:56:00 volumio sudo[374]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:00 volumio sudo[374]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:00 volumio sudo[376]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 02:56:00 volumio sudo[376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:00 volumio volumio[32628]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:00 volumio volumio[32628]: info: ___________ START PLUGINS ___________
Dec 09 02:56:00 volumio volumio[32628]: info: ControllerMpd::onStart: Initializing MPD
Dec 09 02:56:00 volumio volumio[32628]: info: Creating MPD Configuration file
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 09 02:56:00 volumio sudo[384]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 02:56:00 volumio sudo[384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560136] CoreMusicLibrary::Adding element Media Servers
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio sudo[384]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:00 volumio sudo[386]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 02:56:00 volumio sudo[386]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:00 volumio volumio[32628]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:00 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 02:56:00 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 02:56:00 volumio systemd[1]: mpd.service: Consumed 4.562s CPU time.
Dec 09 02:56:00 volumio volumio[32628]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560251] CoreMusicLibrary::Adding element Last_100
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 02:56:00 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:00 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560259] CoreMusicLibrary::Adding element Webradio
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 02:56:00 volumio volumio[32628]: info: Initializing BBC Radios
Dec 09 02:56:00 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 02:56:00 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560340] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560351] CoreMusicLibrary::Adding element SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: info: Creating Spotify config file
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:00 volumio sudo[414]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 02:56:00 volumio sudo[414]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 02:56:00 volumio sudo[414]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:00 volumio volumio[32628]: info: [squeezelite_mc] Starting proxy server...
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560701] CoreMusicLibrary::Adding element YouTube2
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube2
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560720] CoreMusicLibrary::Adding element YouTube Music
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube2
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube Music
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560732] CoreMusicLibrary::Adding element Podcast
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube2
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube Music
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Podcast
Dec 09 02:56:00 volumio volumio-remote-updater[9752]: [2025-12-09 02:56:00] [connect] Successful connection
Dec 09 02:56:00 volumio volumio[32628]: info: Loading i18n strings for locale en
Dec 09 02:56:00 volumio volumio[32628]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 02:56:00 volumio volumio[32628]: Updating browse sources language
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube2
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube Music
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Podcast
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube2
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube Music
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Podcast
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:00 volumio volumio[32628]: info: [1765270560780] CoreMusicLibrary::Adding element Volusonic
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube2
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source YouTube Music
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Podcast
Dec 09 02:56:00 volumio volumio[32628]: Cannot find translation for source Volusonic
Dec 09 02:56:00 volumio volumio[32628]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 09 02:56:00 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 09 02:56:00 volumio volumio[32628]: info: Volumio Calling Home
Dec 09 02:56:00 volumio volumio[32628]: info: [squeezelite_mc] Proxy server started on port 39703
Dec 09 02:56:00 volumio volumio[32628]: info: Preparing to generate the ALSA configuration file
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 02:56:01 volumio volumio[32628]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 02:56:01 volumio volumio[32628]: info: Reading ALSA contributions from plugins.
Dec 09 02:56:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44.
Dec 09 02:56:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:01 volumio volumio[32628]: info: MPD Permissions set
Dec 09 02:56:01 volumio volumio[32628]: info: MPD Permissions set
Dec 09 02:56:01 volumio volumio-remote-updater[9752]: [2025-12-09 02:56:01] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765270560 101
Dec 09 02:56:01 volumio volumio[32628]: 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 09 02:56:01 volumio volumio[32628]: info: Spotify config file written
Dec 09 02:56:01 volumio go-librespot[422]: go-librespot daemon starting...
Dec 09 02:56:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:01 volumio sudo[426]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 09 02:56:01 volumio sudo[426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:01 volumio go-librespot[427]: time="2025-12-09T02:56:01-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:01 volumio go-librespot[427]: time="2025-12-09T02:56:01-06:00" level=debug msg="app state loaded"
Dec 09 02:56:01 volumio go-librespot[427]: time="2025-12-09T02:56:01-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:01 volumio go-librespot[427]: time="2025-12-09T02:56:01-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:01 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon...
Dec 09 02:56:01 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully.
Dec 09 02:56:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:01 volumio volumio[32628]: 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 09 02:56:01 volumio volumio[32628]: info: VolumeController:: Volume=86 Mute =false
Dec 09 02:56:01 volumio volumio[32628]: info: CoreStateMachine::pushState
Dec 09 02:56:01 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::volumioPushState
Dec 09 02:56:01 volumio volumio[32628]: info: [squeezelite_mc] Server discovery started
Dec 09 02:56:01 volumio volumio[32628]: info: [squeezelite_mc] Player finder started
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero  2>&1 || true
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:01 volumio go-librespot[434]: go-librespot daemon starting...
Dec 09 02:56:01 volumio sudo[426]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="app state loaded"
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:01 volumio volumio[32628]: info: No need to fix Spotify hosts
Dec 09 02:56:01 volumio volumio[32628]: 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 09 02:56:01 volumio volumio[32628]: info: Volumio called home
Dec 09 02:56:01 volumio volumio[32628]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 09 02:56:01 volumio volumio[32628]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 02:56:01 volumio volumio[32628]: 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 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=info msg="zeroconf server listening on port 36315"
Dec 09 02:56:01 volumio volumio[32628]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 02:56:01 volumio volumio[32628]: SPOTIFY: BQBBJ698yyQrjuHyXn3t0ndV8_SInLe4eiiLECqIDRP1w8E2-s_j_lVXWUZk0FtNrfgewN0jrGWBnkp8Qq8hphJxKSNpS0xmt4IFJspy0fH997WnHXKDGCyjr5nRBsuzgf4XtPe1UHfE3rcxHnKmywkHxTlHmP1kCeAePb1lwwi9t7V5KQwYkGmHFto3Eqn7HYR-D8D7IY21PMrotJhZt5L8-NPySpBs9Beek-c
Dec 09 02:56:01 volumio volumio[32628]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 02:56:01 volumio volumio[32628]: info: New Spotify access token = BQBBJ698yyQrjuHyXn3t0ndV8_SInLe4eiiLECqIDRP1w8E2-s_j_lVXWUZk0FtNrfgewN0jrGWBnkp8Qq8hphJxKSNpS0xmt4IFJspy0fH997WnHXKDGCyjr5nRBsuzgf4XtPe1UHfE3rcxHnKmywkHxTlHmP1kCeAePb1lwwi9t7V5KQwYkGmHFto3Eqn7HYR-D8D7IY21PMrotJhZt5L8-NPySpBs9Beek-c
Dec 09 02:56:01 volumio volumio[32628]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 09 02:56:01 volumio volumio[32628]: 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 09 02:56:01 volumio volumio[32628]: info: Starting Shairport Sync
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="obtained new client token: AABu8DzXR5+uGXMjsnYQIEjvp318OGxRMPI93+7tqmQMzxh3M2JJrggydy42qaM59baODQM3MYT1p44Bc7cwlyVGsblohJOQetaWAsrcbGc/7vC4B4nehuJVrrEpwrkt7W4y/KLHKCeou1OlyUINjQFsD7UYnJtOjSBrDf2AqUebg/Ye3S8yGEz1pLeU7uXA6+LCYoPhLKk5JImiVIADXT9KUXU4tyd5AVt7iWDYmXRVOJudcawCjonbeQ=="
Dec 09 02:56:01 volumio volumio[32628]: info: Starting Shairport Sync
Dec 09 02:56:01 volumio volumio[32628]: info: Starting Shairport Sync
Dec 09 02:56:01 volumio sudo[457]:  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 09 02:56:01 volumio sudo[457]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:01 volumio sudo[459]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:01 volumio sudo[459]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:01 volumio sudo[457]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:01 volumio sudo[462]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:01 volumio sudo[462]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:01 volumio sudo[463]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:01 volumio sudo[463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:01 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56:01-06:00" level=debug msg="completed challenge"
Dec 09 02:56:01 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 02:56:01 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:01 volumio systemd[1]: shairport-sync.service: Consumed 1.954s CPU time.
Dec 09 02:56:01 volumio go-librespot[440]: time="2025-12-09T02:56: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 09 02:56:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:02 volumio volumio[32628]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 09 02:56:02 volumio volumio[32628]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 02:56:02 volumio volumio[32628]: info: Output device has changed, restarting MPD
Dec 09 02:56:02 volumio volumio[32628]: info: Output device has changed, restarting Shairport Sync
Dec 09 02:56:02 volumio sudo[473]:  volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 09 02:56:02 volumio sudo[473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:02 volumio sudo[459]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio sudo[475]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 02:56:02 volumio sudo[475]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:02 volumio volumio[32628]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:02 volumio sudo[462]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio sudo[473]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio sudo[475]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 02:56:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 02:56:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:02 volumio sudo[478]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 02:56:02 volumio sudo[478]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:02 volumio sudo[463]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 02:56:02 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 02:56:02 volumio systemd[1]: mpd.service: Consumed 1.805s CPU time.
Dec 09 02:56:02 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 02:56:02 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:02 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 02:56:02 volumio volumio[32628]: info: MPD Permissions set
Dec 09 02:56:02 volumio volumio[32628]: info: Shairport-Sync Started
Dec 09 02:56:02 volumio volumio[32628]: Error adding Membership: Error: addMembership EINVAL
Dec 09 02:56:02 volumio volumio[32628]: info: Shairport-Sync Started
Dec 09 02:56:02 volumio volumio[32628]: info: Shairport-Sync Started
Dec 09 02:56:02 volumio volumio[32628]: 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 09 02:56:02 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:02 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:02 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:02 volumio volumio[32628]: info: Starting Shairport Sync
Dec 09 02:56:02 volumio volumio[32628]: 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 09 02:56:02 volumio volumio[32628]: info: Spotify Successfully logged in
Dec 09 02:56:02 volumio sudo[516]:  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 09 02:56:02 volumio sudo[516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:02 volumio volumio[32628]: info: [1765270562551] CoreMusicLibrary::Adding element Spotify
Dec 09 02:56:02 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:02 volumio volumio[32628]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:02 volumio volumio[32628]: Cannot find translation for source SoundCloud
Dec 09 02:56:02 volumio volumio[32628]: Cannot find translation for source YouTube2
Dec 09 02:56:02 volumio volumio[32628]: Cannot find translation for source YouTube Music
Dec 09 02:56:02 volumio volumio[32628]: Cannot find translation for source Podcast
Dec 09 02:56:02 volumio volumio[32628]: Cannot find translation for source Volusonic
Dec 09 02:56:02 volumio volumio[32628]: Cannot find translation for source Spotify
Dec 09 02:56:02 volumio sudo[523]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:02 volumio sudo[523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:02 volumio sudo[516]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio sudo[514]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 02:56:02 volumio sudo[514]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 02:56:02 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload  || true
Dec 09 02:56:02 volumio sudo[514]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 02:56:02 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 02:56:02 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:02 volumio sudo[529]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 09 02:56:02 volumio sudo[529]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:02 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:02 volumio sudo[523]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:02 volumio systemd[1]: Reloading.
Dec 09 02:56:02 volumio volumio[32628]: info: Shairport-Sync Started
Dec 09 02:56:02 volumio volumio[32628]: info: [squeezelite_mc] Notification listener started
Dec 09 02:56:02 volumio volumio[32628]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 02:56:03 volumio volumio[32628]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"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"}},{"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 09 02:56:03 volumio volumio[32628]: 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 09 02:56:03 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:03 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:03 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:03 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:04 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 09 02:56:04 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 09 02:56:04 volumio sudo[529]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:04 volumio volumio[32628]: info: go-librespot daemon successfully initialized
Dec 09 02:56:04 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:04 volumio sudo[564]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:04 volumio sudo[564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:04 volumio volumio[32628]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:04 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:04 volumio sudo[564]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:04 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 09 02:56:04 volumio sudo[567]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 09 02:56:04 volumio sudo[567]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:04 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 02:56:05 volumio volumio[32628]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 09 02:56:05 volumio volumio[32628]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:05 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1.
Dec 09 02:56:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:05 volumio go-librespot[569]: go-librespot daemon starting...
Dec 09 02:56:05 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 09 02:56:05 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=debug msg="app state loaded"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:05 volumio sudo[567]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-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 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-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 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=info msg="zeroconf server listening on port 36073"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=debug msg="obtained new client token: AABMw+cWeKW7ihgj4cAID2avFPXXmQCjOpIofhCfpXj9oeE4HfuftRvUgwOzHbnNLUEi8p7qoJwab+Aq1rNztau1WC1iyKD71T0YOaVychfeGORrKnF0H42etBI+ePPWjEiT1SHc7msbu07tT5vhyMT8EWlU85L0llGPDWWF0hNDPiM65GZiaHV2v0N41OutZlNmh2s5+j0OPcYuY64KTyA7iOHjNjJmpTeV/yY1s+200Rhi4nAMWBKZxw=="
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56:05-06:00" level=debug msg="completed challenge"
Dec 09 02:56:05 volumio go-librespot[570]: time="2025-12-09T02:56: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 09 02:56:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:05 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:05 volumio sudo[578]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:05 volumio sudo[578]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:05 volumio sudo[578]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:05 volumio volumio[32628]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 09 02:56:05 volumio sudo[582]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 09 02:56:05 volumio sudo[582]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:05 volumio sudo[582]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:05 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 09 02:56:06 volumio sudo[585]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 09 02:56:06 volumio sudo[585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:06 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 02:56:06 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 02:56:06 volumio sudo[585]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:06 volumio volumio[32628]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 09 02:56:06 volumio volumio[32628]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 02:56:06 volumio volumio[32628]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"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"}},{"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 09 02:56:06 volumio volumio[32628]: 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 09 02:56:06 volumio mpd[528]: 2025-12-09T02:56:06 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 09 02:56:06 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 09 02:56:06 volumio sudo[376]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:06 volumio sudo[478]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:06 volumio sudo[386]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:06 volumio volumio[32628]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 02:56:06 volumio volumio[32628]:   assert.ok(self.idling)
Dec 09 02:56:06 volumio volumio[32628]: error: The expression evaluated to a falsy value:
Dec 09 02:56:06 volumio volumio[32628]:   assert.ok(self.idling)
Dec 09 02:56:06 volumio volumio[32628]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 02:56:06 volumio volumio[32628]:   assert.ok(self.idling)
Dec 09 02:56:06 volumio volumio[32628]: error: The expression evaluated to a falsy value:
Dec 09 02:56:06 volumio volumio[32628]:   assert.ok(self.idling)
Dec 09 02:56:06 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:06 volumio volumio[32628]: error: updateQueue error: null
Dec 09 02:56:06 volumio volumio[32628]: info: MPD running with PID528
Dec 09 02:56:06 volumio volumio[32628]:  ,establishing connection
Dec 09 02:56:06 volumio volumio[32628]: error: updateQueue error: null
Dec 09 02:56:06 volumio sudo[598]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:06 volumio sudo[598]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:06 volumio sudo[598]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:07 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:07 volumio sudo[601]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:07 volumio sudo[601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:07 volumio volumio[32628]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:07 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:07 volumio sudo[601]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:07 volumio volumio[32628]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:07 volumio volumio[32628]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:56:07 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:07 volumio sudo[618]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:08 volumio sudo[618]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:08 volumio sudo[618]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:08 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:08 volumio sudo[624]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:08 volumio sudo[624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:08 volumio sudo[624]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2.
Dec 09 02:56:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:09 volumio go-librespot[626]: go-librespot daemon starting...
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=debug msg="app state loaded"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:09 volumio volumio[32628]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:09 volumio sudo[634]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:09 volumio sudo[634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:09 volumio sudo[634]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:09 volumio volumio[32628]: info: Completed starting Core Plugins
Dec 09 02:56:09 volumio volumio[32628]: info: -------------------------------------------
Dec 09 02:56:09 volumio volumio[32628]: info: -----    MyVolumio plugins startup     ----
Dec 09 02:56:09 volumio volumio[32628]: info: -------------------------------------------
Dec 09 02:56:09 volumio volumio[32628]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-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 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-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 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=info msg="zeroconf server listening on port 34961"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=debug msg="obtained new client token: AACx/XkLS41wBHSUYEeoLu5MEPv8rPYQJuTQTrbo9lcrojcfp1dJDeeEThk7mUrkAXrJjSeX3yxbwTj0AFSljcAEnt/Tff/gz7aJILYBFzwl0Yc1MgsGW9u3YX7WKgRwhbcSZJr4SK8ePyEuW/J+QBR82W/Bdl1RL63sJSbZ0jVoM7EVomUrcIdba6GaiHB0Dezw4bq2EbVbC746Rh8DfEUQ/r12drmGK9bsEEpWYgv8dv3q+9iuUOC9ag=="
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56:09-06:00" level=debug msg="completed challenge"
Dec 09 02:56:09 volumio go-librespot[627]: time="2025-12-09T02:56: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 09 02:56:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:09 volumio sudo[639]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 02:56:09 volumio sudo[639]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:09 volumio sudo[641]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 02:56:09 volumio sudo[641]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:09 volumio sudo[643]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 02:56:09 volumio sudo[643]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:09 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 09 02:56:09 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 09 02:56:09 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 09 02:56:09 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 09 02:56:09 volumio sudo[639]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:09 volumio sudo[641]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:09 volumio mpd_monitor.sh[647]: MPD Monitor Service: Starting MPD Monitor Service
Dec 09 02:56:09 volumio sudo[643]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:09 volumio volumio[32628]: info: Successfully started MPD Monitor
Dec 09 02:56:09 volumio volumio[32628]: info: Successfully started MPD Monitor
Dec 09 02:56:09 volumio volumio[32628]: info: Successfully started MPD Monitor
Dec 09 02:56:10 volumio volumio[32628]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:10 volumio volumio[32628]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:56:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3.
Dec 09 02:56:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:12 volumio go-librespot[651]: go-librespot daemon starting...
Dec 09 02:56:12 volumio go-librespot[652]: time="2025-12-09T02:56:12-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:12 volumio go-librespot[652]: time="2025-12-09T02:56:12-06:00" level=debug msg="app state loaded"
Dec 09 02:56:12 volumio go-librespot[652]: time="2025-12-09T02:56:12-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:12 volumio go-librespot[652]: time="2025-12-09T02:56:12-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:13 volumio go-librespot[652]: time="2025-12-09T02:56: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-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 02:56:13 volumio go-librespot[652]: time="2025-12-09T02:56:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 02:56:13 volumio go-librespot[652]: time="2025-12-09T02:56:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 02:56:13 volumio go-librespot[652]: time="2025-12-09T02:56:13-06:00" level=info msg="zeroconf server listening on port 44483"
Dec 09 02:56:13 volumio go-librespot[652]: time="2025-12-09T02:56:13-06:00" level=debug msg="obtained new client token: AADA+/1P6xsgTZ3yksNgMHqgGV65QZhH3FPgM3JOK3k7wBn9BDyCX4EDLCJZKRBnwTOofMa7eN1giXaLRU3GsE3jXSJkgTel4XlHAj4JAIbwn2ARWYcPdSxaA/hzSa/a2SFRse+ulF9fllNAAgDFb5wOI/xOzRITLUoICyadYBUxW6CLG1Q2yIkTRnBGjkrszgkNcertYj8tSIh852b8ie20Q55KWrTayHX00vZSeeAhCXJwIJ72Yg4="
Dec 09 02:56:13 volumio go-librespot[652]: time="2025-12-09T02:56:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:14 volumio volumio[32628]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:14 volumio go-librespot[652]: time="2025-12-09T02:56:14-06:00" level=debug msg="new websocket client"
Dec 09 02:56:14 volumio volumio[32628]: info: Connection to go-librespot Websocket established
Dec 09 02:56:14 volumio go-librespot[652]: time="2025-12-09T02:56:14-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:14 volumio go-librespot[652]: time="2025-12-09T02:56:14-06:00" level=debug msg="completed challenge"
Dec 09 02:56:14 volumio go-librespot[652]: time="2025-12-09T02:56: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 09 02:56:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:14 volumio volumio[32628]: info: Connection to go-librespot Websocket closed
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 09 02:56:17 volumio volumio[32628]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 09 02:56:17 volumio volumio[32628]: info: Adding plugin multiroom to MyMusic Plugins
Dec 09 02:56:17 volumio volumio[32628]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 09 02:56:17 volumio volumio[32628]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 09 02:56:17 volumio volumio[32628]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 09 02:56:17 volumio volumio[32628]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 09 02:56:17 volumio volumio[32628]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 09 02:56:17 volumio volumio[32628]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 09 02:56:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4.
Dec 09 02:56:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:17 volumio go-librespot[663]: go-librespot daemon starting...
Dec 09 02:56:17 volumio go-librespot[682]: time="2025-12-09T02:56:17-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:17 volumio go-librespot[682]: time="2025-12-09T02:56:17-06:00" level=debug msg="app state loaded"
Dec 09 02:56:17 volumio go-librespot[682]: time="2025-12-09T02:56:17-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:17 volumio go-librespot[682]: time="2025-12-09T02:56:17-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:18 volumio go-librespot[682]: time="2025-12-09T02:56: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-gew1.spotify.com:80]"
Dec 09 02:56:18 volumio go-librespot[682]: time="2025-12-09T02:56:18-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 02:56:18 volumio go-librespot[682]: time="2025-12-09T02:56:18-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 02:56:18 volumio go-librespot[682]: time="2025-12-09T02:56:18-06:00" level=info msg="zeroconf server listening on port 34945"
Dec 09 02:56:18 volumio go-librespot[682]: time="2025-12-09T02:56:18-06:00" level=debug msg="obtained new client token: AAApuOqwN7KJYt4AYuCtFTZIt9p1kDspPBsQUj06DedpEItYROLEIG+gMnrEBLw1uF1QxDaQDaVB07sIvuNjY7AG8LmJFMLjUgL7uR33DlgT5etPnMiCsEQrDdV28B3G92tLYnzfZ7LWKPCi+PumTLHBLshH0T5hz78A+qbkWTZfnpVWDCTT4Cf0KNkx/I8jpJgx9QB18ug8FusszCzQxWFh6B65t1pRXf2v6Acw6fvjSgFUjEiAAqs="
Dec 09 02:56:18 volumio go-librespot[682]: time="2025-12-09T02:56:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:18 volumio volumio[32628]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 09 02:56:18 volumio volumio[32628]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 09 02:56:18 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:18 volumio volumio[32628]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:18 volumio volumio[32628]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 09 02:56:18 volumio volumio[32628]: info: MyVolumio login type: Token
Dec 09 02:56:18 volumio volumio[32628]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 09 02:56:18 volumio volumio[32628]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 09 02:56:19 volumio volumio[32628]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 09 02:56:19 volumio volumio[32628]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 09 02:56:19 volumio volumio[32628]: info: Streaming services startup
Dec 09 02:56:19 volumio volumio[32628]: info: Starting Streaming Daemon
Dec 09 02:56:19 volumio sudo[691]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 02:56:19 volumio sudo[691]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:19 volumio volumio[32628]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 09 02:56:19 volumio sudo[691]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:19 volumio volumio[32628]: info: Getting Spotify volume
Dec 09 02:56:19 volumio volumio[32628]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:19 volumio volumio[32628]: error: Cannot start Volumio Streaming Daemon
Dec 09 02:56:19 volumio volumio[32628]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 02:56:19 volumio volumio[32628]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 02:56:19 volumio go-librespot[682]: time="2025-12-09T02:56:19-06:00" level=debug msg="new websocket client"
Dec 09 02:56:19 volumio volumio[32628]: 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 09 02:56:19 volumio volumio[32628]: info: Connection to go-librespot Websocket established
Dec 09 02:56:19 volumio volumio[32628]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:19 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:19 volumio volumio[32628]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86
Dec 09 02:56:19 volumio volumio[32628]: SPOTIFY: SPOTIFY VOLUME undefined
Dec 09 02:56:19 volumio volumio[32628]: SPOTIFY: VOLUMIO VOLUME 86
Dec 09 02:56:19 volumio volumio[32628]: info: Aligning Spotify Volume to Volumio Volume
Dec 09 02:56:19 volumio volumio[32628]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:19 volumio volumio[32628]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:19 volumio volumio[32628]: info: Setting Spotify Volume from Volumio: 86
Dec 09 02:56:19 volumio volumio[32628]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 09 02:56:20 volumio volumio[32628]: info: MyVolumio token set successfully
Dec 09 02:56:20 volumio volumio[32628]: info: MYVOLUMIO: Adding device
Dec 09 02:56:20 volumio volumio[32628]: info: MYVOLUMIO: Evaluating Server
Dec 09 02:56:20 volumio go-librespot[682]: time="2025-12-09T02:56:20-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:20 volumio go-librespot[682]: time="2025-12-09T02:56:20-06:00" level=debug msg="completed challenge"
Dec 09 02:56:20 volumio go-librespot[682]: time="2025-12-09T02:56: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 09 02:56:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:20 volumio volumio[32628]: info: MyVolumio status changed
Dec 09 02:56:20 volumio volumio[32628]: info: Streaming services startup
Dec 09 02:56:20 volumio volumio[32628]: info: Starting Streaming Daemon
Dec 09 02:56:20 volumio volumio[32628]: info: Removing browser output: myVolumio user plan is not superstar
Dec 09 02:56:20 volumio volumio[32628]: info: Removing audio output:
Dec 09 02:56:20 volumio volumio[32628]: info: Stoppping Tunnel 1
Dec 09 02:56:20 volumio sudo[726]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 02:56:20 volumio sudo[726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:20 volumio volumio[32628]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 02:56:20 volumio sudo[728]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 09 02:56:20 volumio sudo[728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:20 volumio volumio[32628]: Error: socket hang up
Dec 09 02:56:20 volumio volumio[32628]:     at connResetException (node:internal/errors:720:14)
Dec 09 02:56:20 volumio volumio[32628]:     at Socket.socketOnEnd (node:_http_client:519:23)
Dec 09 02:56:20 volumio volumio[32628]:     at Socket.emit (node:events:526:35)
Dec 09 02:56:20 volumio volumio[32628]:     at endReadableNT (node:internal/streams/readable:1376:12)
Dec 09 02:56:20 volumio volumio[32628]:     at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 09 02:56:20 volumio volumio[32628]:   code: 'ECONNRESET',
Dec 09 02:56:20 volumio volumio[32628]:   response: undefined
Dec 09 02:56:20 volumio volumio[32628]: }
Dec 09 02:56:20 volumio volumio[32628]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 02:56:20 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 09 02:56:20 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 09 02:56:20 volumio sudo[726]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:20 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 09 02:56:20 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 09 02:56:20 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 09 02:56:20 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 09 02:56:20 volumio sudo[728]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:21 volumio sudo[746]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 02:55'
Dec 09 02:56:21 volumio sudo[746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:21 volumio sudo[746]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:22 volumio volumio-remote-updater[9752]: [2025-12-09 02:56:22] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 09 02:56:22 volumio volumio-remote-updater[9752]: [2025-12-09 02:56:22] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 09 02:56:22 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:22 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 09 02:56:22 volumio systemd[1]: volumio.service: Consumed 46.269s CPU time.
Dec 09 02:56:22 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 02:56:22 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 02:56:22 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 24007.
Dec 09 02:56:22 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 02:56:22 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 09 02:56:22 volumio systemd[1]: volumio.service: Consumed 46.269s CPU time.
Dec 09 02:56:22 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 09 02:56:22 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 02:56:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5.
Dec 09 02:56:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:23 volumio go-librespot[777]: go-librespot daemon starting...
Dec 09 02:56:23 volumio go-librespot[778]: time="2025-12-09T02:56:23-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:23 volumio go-librespot[778]: time="2025-12-09T02:56:23-06:00" level=debug msg="app state loaded"
Dec 09 02:56:23 volumio go-librespot[778]: time="2025-12-09T02:56:23-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:23 volumio go-librespot[778]: time="2025-12-09T02:56:23-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56: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-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56:24-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56:24-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56:24-06:00" level=info msg="zeroconf server listening on port 46875"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56:24-06:00" level=debug msg="obtained new client token: AABqswxxp2i8K9gN+ne43s3cnzp+OELhZNS0ILFWpyY3o1iCX1L55lsIXdM9ECQFND1H7g+LS7GoU9Rnt2SLXfZCNLP6QWxGDkBz1zTAQ0debxHQ1acz3ifaEOsBj24HvSbXYyVqFhJlJFNCVLy9BfqFAr6JMTaPXw0M9C5JUJwELJ8I2WjJS6fLRRPmPLkGgX4zA6ZHnpAVl3IXZdEze41UKEjpKjoMdc8qezTepf5IbC0PCZIhcos="
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56:24-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56:24-06:00" level=debug msg="completed challenge"
Dec 09 02:56:24 volumio go-librespot[778]: time="2025-12-09T02:56: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 09 02:56:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:24 volumio volumio[762]: info: -------------------------------------------
Dec 09 02:56:24 volumio volumio[762]: info: -----            Volumio3              ----
Dec 09 02:56:24 volumio volumio[762]: info: -------------------------------------------
Dec 09 02:56:24 volumio volumio[762]: info: -----          System startup          ----
Dec 09 02:56:24 volumio volumio[762]: info: -------------------------------------------
Dec 09 02:56:25 volumio volumio[762]: info: MYVOLUMIO Environment detected
Dec 09 02:56:25 volumio volumio[762]: info: Plugin folders cleanup
Dec 09 02:56:25 volumio volumio[762]: info: Scanning into folder /volumio/app/plugins/
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category audio_interface
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category miscellanea
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category music_service
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category plugins.json
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category system_controller
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category user_interface
Dec 09 02:56:25 volumio volumio[762]: info: Scanning into folder /data/plugins/
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category audio_interface
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category music_service
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category system_controller
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category system_hardware
Dec 09 02:56:25 volumio volumio[762]: info: Scanning category user_interface
Dec 09 02:56:25 volumio volumio[762]: info: Plugin folders cleanup completed
Dec 09 02:56:25 volumio volumio[762]: info: -------------------------------------------
Dec 09 02:56:25 volumio volumio[762]: info: -----      Core plugins startup        ----
Dec 09 02:56:25 volumio volumio[762]: info: -------------------------------------------
Dec 09 02:56:25 volumio volumio[762]: info: Loading plugins from folder /volumio/app/plugins/
Dec 09 02:56:25 volumio volumio[762]: info: Adding plugin upnp to MyMusic Plugins
Dec 09 02:56:25 volumio volumio[762]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 09 02:56:25 volumio volumio[762]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 09 02:56:25 volumio volumio[762]: info: Loading plugins from folder /data/plugins/
Dec 09 02:56:25 volumio volumio[762]: info: Loading plugin "system"...
Dec 09 02:56:25 volumio volumio[762]: info: Loading plugin "appearance"...
Dec 09 02:56:26 volumio volumio[762]: info: Loading plugin "network"...
Dec 09 02:56:26 volumio volumio[762]: info: Refreshing Cached IP Addresses
Dec 09 02:56:26 volumio sudo[803]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 02:56:26 volumio sudo[805]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 02:56:26 volumio sudo[805]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:26 volumio sudo[803]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:26 volumio volumio[762]: info: Loading plugin "services"...
Dec 09 02:56:26 volumio sudo[803]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:26 volumio sudo[805]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:26 volumio volumio[762]: info: Loading plugin "alsa_controller"...
Dec 09 02:56:26 volumio sudo[812]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 09 02:56:26 volumio sudo[812]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:26 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 02:56:26 volumio volumio[762]: info: Loading plugin "wizard"...
Dec 09 02:56:26 volumio volumio[762]: info: Loading plugin "networkfs"...
Dec 09 02:56:26 volumio volumio[762]: info: Starting Udev Watcher for removable devices
Dec 09 02:56:27 volumio volumio[762]: info: Ignoring mount for partition: boot
Dec 09 02:56:27 volumio volumio[762]: info: Ignoring mount for partition: volumio
Dec 09 02:56:27 volumio volumio[762]: info: Ignoring mount for partition: volumio_data
Dec 09 02:56:27 volumio volumio[762]: info: Mounting Device Wikipedia
Dec 09 02:56:27 volumio sudo[843]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 09 02:56:27 volumio sudo[843]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:27 volumio sudo[843]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:27 volumio volumio[762]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 02:56:27 volumio volumio[762]:        dmesg(1) may have more information after failed mount system call.
Dec 09 02:56:27 volumio volumio[762]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 09 02:56:27 volumio volumio[762]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 02:56:27 volumio volumio[762]:        dmesg(1) may have more information after failed mount system call.
Dec 09 02:56:27 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 02:56:27 volumio volumio[762]: info: Loading plugin "volumio_command_line_client"...
Dec 09 02:56:27 volumio volumio[762]: info: Loading plugin "upnp"...
Dec 09 02:56:27 volumio volumio[762]: info: [1765270587106] Starting Upmpd Daemon
Dec 09 02:56:27 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 02:56:27 volumio volumio[762]: info: Loading plugin "my_music"...
Dec 09 02:56:27 volumio volumio[762]: info: Loading plugin "mpd"...
Dec 09 02:56:27 volumio volumio-remote-updater[9752]: [2025-12-09 02:56:27] [connect] Successful connection
Dec 09 02:56:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6.
Dec 09 02:56:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:27 volumio sudo[812]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:27 volumio volumio[762]: info: Loading plugin "upnp_browser"...
Dec 09 02:56:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:27 volumio go-librespot[845]: go-librespot daemon starting...
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=debug msg="app state loaded"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=info msg="zeroconf server listening on port 41317"
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=debug msg="obtained new client token: AABw1QA2kQpAd15iTrVLospiSdhK6hxEgC8lWfPfUuEN/oL6cVKOO/eU6+aj+lGFwCal1pFb04ypYvZJ9uE7X49lHjR0ZMX/fL+i5BpyqkOvJMuA0IizURU+CQk181uMf2PJC9A69+rOsLCTwlRkMzg8/ocpT+4YTc+IzGbytWNhP7DOgPkwJ0YLze/9FHkXZHJUs+l5aOGaizPDNTlnAYW+3Q/lb0wVkedTB2jWFlho2Wnep2NLFXF+6w=="
Dec 09 02:56:27 volumio go-librespot[846]: time="2025-12-09T02:56:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:28 volumio go-librespot[846]: time="2025-12-09T02:56:28-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:28 volumio go-librespot[846]: time="2025-12-09T02:56:28-06:00" level=debug msg="completed challenge"
Dec 09 02:56:28 volumio go-librespot[846]: time="2025-12-09T02:56: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 09 02:56:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:28 volumio volumio[762]: info: Loading plugin "alarm-clock"...
Dec 09 02:56:29 volumio volumio[762]: info: Loading plugin "airplay_emulation"...
Dec 09 02:56:29 volumio volumio[762]: info: Starting Shairport Sync
Dec 09 02:56:29 volumio volumio[762]: info: Loading plugin "last_100"...
Dec 09 02:56:29 volumio volumio[762]: info: Loading plugin "webradio"...
Dec 09 02:56:29 volumio volumio[762]: info: Loading plugin "i2s_dacs"...
Dec 09 02:56:29 volumio volumio[762]: info: I2S DAC not set, start Auto-detection
Dec 09 02:56:29 volumio volumio[762]: info: Loading plugin "volumiodiscovery"...
Dec 09 02:56:29 volumio volumio[762]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 02:56:29 volumio volumio[762]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 02:56:29 volumio volumio[762]: *** WARNING *** For more information see 
Dec 09 02:56:29 volumio volumio[762]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 02:56:29 volumio volumio[762]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 02:56:29 volumio volumio[762]: *** WARNING *** For more information see 
Dec 09 02:56:29 volumio node[762]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 02:56:29 volumio node[762]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 02:56:29 volumio node[762]: *** WARNING *** For more information see 
Dec 09 02:56:29 volumio node[762]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 02:56:29 volumio node[762]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 02:56:29 volumio node[762]: *** WARNING *** For more information see 
Dec 09 02:56:29 volumio volumio[762]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 09 02:56:29 volumio volumio[762]: info: Discovery: Started advertising with name: Volumio
Dec 09 02:56:29 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 02:56:29 volumio volumio[762]: info: Loading plugin "bandcamp"...
Dec 09 02:56:30 volumio volumio[762]: info: Plugin calmradio is not enabled
Dec 09 02:56:30 volumio volumio[762]: info: Loading plugin "soundcloud"...
Dec 09 02:56:30 volumio volumio[762]: info: Loading plugin "spop"...
Dec 09 02:56:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7.
Dec 09 02:56:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:31 volumio go-librespot[859]: go-librespot daemon starting...
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="app state loaded"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=info msg="zeroconf server listening on port 42067"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="obtained new client token: AACha+qJogzbtFfHc5fXC4k41SPZ/8Do+5UL1Ckrk5JWC0zvf5f4B/DHr175rBv2iANli0EQ0y5NBRMvSNpBrlDSkK+SZ5w4t1uUg0EHWuXSKCT+HOIlmTlp6jbEHIMokspjzzCSeQDyWr1B22jFWe79WnqizgqjorDLQFGOEvszTdRe3BKueeQ7XceGP7qUQt2udDS2MwGd51Sv7eJnLjr6WJbmrfsvBsYX/Zad3kGIC4YIVy1VoLQgKQ=="
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=debug msg="completed challenge"
Dec 09 02:56:31 volumio go-librespot[860]: time="2025-12-09T02:56:31-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 02:56:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:31 volumio volumio[762]: info: Loading plugin "squeezelite_mc"...
Dec 09 02:56:32 volumio volumio[762]: info: Loading plugin "youtube2"...
Dec 09 02:56:33 volumio volumio[762]: info: Loading plugin "ytcr"...
Dec 09 02:56:34 volumio volumio[762]: info: Loading plugin "ytmusic"...
Dec 09 02:56:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8.
Dec 09 02:56:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:35 volumio go-librespot[868]: go-librespot daemon starting...
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=debug msg="app state loaded"
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:35 volumio volumio[762]: info: Plugin now_playing is not enabled
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "outputs"...
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "albumart"...
Dec 09 02:56:35 volumio volumio[762]: info: Plugin example_plugin is not enabled
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "inputs"...
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "updater_comm"...
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-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 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-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 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-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 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=info msg="zeroconf server listening on port 44255"
Dec 09 02:56:35 volumio volumio[762]: info: Plugin mpdemulation is not enabled
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "rest_api"...
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "websocket"...
Dec 09 02:56:35 volumio volumio[762]: info: Starting Socket.io Server version 1.7.4
Dec 09 02:56:35 volumio volumio[762]: info: Plugin fusiondsp is not enabled
Dec 09 02:56:35 volumio volumio[762]: info: Plugin mpdoutput is not enabled
Dec 09 02:56:35 volumio volumio[762]: info: Plugin RoonBridge is not enabled
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "podcast"...
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=debug msg="obtained new client token: AAD76MoM49qF4rBZcOAk9f9/SC0pXELqCvQzc5/MywsZTLvnBWAbetuFoC9dThEy0Yhn+1o7VBrRlNV+lhBP+yVNOcp74MrBK47Ez5k4MXDL9N9wePhGxkb5vSBZ3jg0Wui5Eb9l6kSJoTZ9EvpUS7q7US/z1xFtAFnVOr7pmz65Xqo/gT6/3TRov7C1erSdbeftjnkr6n43cD/D1WdMsnE0mz4OLqw8lZ2EecheAGcBClIG7VEkXnQhzg=="
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=debug msg="completed challenge"
Dec 09 02:56:35 volumio go-librespot[869]: time="2025-12-09T02:56:35-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 02:56:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:35 volumio volumio[762]: info: ControllerPodcast::constructor
Dec 09 02:56:35 volumio volumio[762]: info: Loading plugin "volusonic"...
Dec 09 02:56:35 volumio volumio[876]: Forking 3 albumart workers
Dec 09 02:56:37 volumio volumio[762]: info: Applying required configuration parameters for plugin volusonic
Dec 09 02:56:37 volumio volumio[762]: info: Loading plugin "backup_restore"...
Dec 09 02:56:37 volumio volumio[886]: Starting albumart workers
Dec 09 02:56:37 volumio volumio[888]: Starting albumart workers
Dec 09 02:56:37 volumio volumio[762]: info: Applying required configuration parameters for plugin backup_restore
Dec 09 02:56:37 volumio volumio[762]: info: Plugin rpi_eeprom_config is not enabled
Dec 09 02:56:37 volumio volumio[762]: info: Plugin rpi_eeprom_updater is not enabled
Dec 09 02:56:37 volumio volumio[762]: info: Loading plugin "scheduledrestart"...
Dec 09 02:56:37 volumio volumio[887]: Starting albumart workers
Dec 09 02:56:37 volumio volumio[762]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 09 02:56:37 volumio volumio[762]: info: Plugin Bluetoothremote is not enabled
Dec 09 02:56:37 volumio volumio[762]: info: Plugin music_services_shield is not enabled
Dec 09 02:56:37 volumio volumio[762]: info: Loading plugin "Systeminfo"...
Dec 09 02:56:38 volumio volumio[762]: info: Plugin peppymeterbasic is not enabled
Dec 09 02:56:38 volumio volumio[762]: info: Loading plugin "peppyspectrum"...
Dec 09 02:56:38 volumio volumio[762]: info: Loading i18n strings for locale en
Dec 09 02:56:38 volumio volumio[762]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 02:56:38 volumio volumio[762]: Updating browse sources language
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::initPlayerControls
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9.
Dec 09 02:56:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:38 volumio volumio[762]: Express server listening on port 3000
Dec 09 02:56:38 volumio volumio[762]:  [Metrics]  WebUI:  14s 450.60ms 
Dec 09 02:56:38 volumio volumio[762]: info: CoreStateMachine::resetVolumioState
Dec 09 02:56:38 volumio volumio[762]: info: CoreStateMachine::getcurrentVolume
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 02:56:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:38 volumio go-librespot[955]: go-librespot daemon starting...
Dec 09 02:56:38 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:38 volumio go-librespot[960]: time="2025-12-09T02:56:38-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:38 volumio go-librespot[960]: time="2025-12-09T02:56:38-06:00" level=debug msg="app state loaded"
Dec 09 02:56:38 volumio go-librespot[960]: time="2025-12-09T02:56:38-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:38 volumio go-librespot[960]: time="2025-12-09T02:56:38-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:38 volumio sudo[967]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 02:56:38 volumio sudo[967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:38 volumio sudo[969]:  volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 02:56:38 volumio sudo[969]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:38 volumio sudo[967]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:38 volumio sudo[969]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:38 volumio volumio[762]: info: Volumio Network Manager: Network status updated: 1
Dec 09 02:56:39 volumio volumio[762]: info: VolumeController:: Volume=86 Mute =false
Dec 09 02:56:39 volumio volumio[762]: info: CoreStateMachine::pushState
Dec 09 02:56:39 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioPushState
Dec 09 02:56:39 volumio volumio[762]: info: CoreStateMachine::updateTrackBlock
Dec 09 02:56:39 volumio volumio[762]: info: CorePlayQueue::getTrackBlock
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-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 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-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 09 02:56:39 volumio volumio[762]: info: Reloading queue from file
Dec 09 02:56:39 volumio volumio[762]: info: CoreStateMachine::setRepeat null single undefined
Dec 09 02:56:39 volumio volumio[762]: info: CoreStateMachine::pushState
Dec 09 02:56:39 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioPushState
Dec 09 02:56:39 volumio volumio[762]: info: CoreStateMachine::setRandom null
Dec 09 02:56:39 volumio volumio[762]: info: CoreStateMachine::pushState
Dec 09 02:56:39 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioPushState
Dec 09 02:56:39 volumio volumio[762]: info: Setting Device type: Raspberry PI
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-06:00" level=info msg="zeroconf server listening on port 37289"
Dec 09 02:56:39 volumio volumio[762]: info: VolumeController:: Volume=86 Mute =false
Dec 09 02:56:39 volumio volumio[762]: info: CoreStateMachine::pushState
Dec 09 02:56:39 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioPushState
Dec 09 02:56:39 volumio volumio[762]: info: Completed loading Core Plugins
Dec 09 02:56:39 volumio volumio[762]: info: Preparing to generate the ALSA configuration file
Dec 09 02:56:39 volumio sudo[986]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 09 02:56:39 volumio sudo[986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-06:00" level=debug msg="obtained new client token: AACrG6TrLqcyMj8ZOWTaTJZZn3IRtSKWIxJtWuorD5ohOhnxAlKqgPpJweUYQUC8EwLvuLBPeiUHrHpOdVoI0/tANpDcaxy++kXxhnirJdBbM5+OU4OIVjB7BEcFIDyVWIJUksaOP/EwZVoCMF0bg0+brzd2NjlefFxhuZl86PjKj5YSoGJDrmLAXF83G6ZhO9zp7Bg/ubditlxXzVFhFyFC4qsFcplMiPwfy6g9vSu4WZcfddocwsQ="
Dec 09 02:56:39 volumio volumio[762]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 02:56:39 volumio volumio[762]: info: Discovery: Found device Volumio
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:39 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:39 volumio volumio[762]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 02:56:39 volumio volumio[762]: info: Reading ALSA contributions from plugins.
Dec 09 02:56:39 volumio volumio[762]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 02:56:39 volumio volumio[762]: info: Output device has changed, restarting MPD
Dec 09 02:56:39 volumio sudo[986]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:39 volumio volumio[762]: info: Output device has changed, restarting Shairport Sync
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:39 volumio sudo[989]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 02:56:39 volumio sudo[989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:39 volumio sudo[989]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:39 volumio sudo[991]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 02:56:39 volumio sudo[991]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:39 volumio volumio[762]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:39 volumio volumio[762]: info: ___________ START PLUGINS ___________
Dec 09 02:56:39 volumio volumio[762]: info: ControllerMpd::onStart: Initializing MPD
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-06:00" level=debug msg="completed challenge"
Dec 09 02:56:39 volumio volumio[762]: info: Creating MPD Configuration file
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:39 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599338] CoreMusicLibrary::Adding element Media Servers
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio sudo[1000]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 02:56:39 volumio sudo[1000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:39 volumio go-librespot[960]: time="2025-12-09T02:56:39-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 02:56:39 volumio sudo[1000]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:39 volumio sudo[1009]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 02:56:39 volumio sudo[1009]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:39 volumio volumio[762]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:39 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 02:56:39 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 02:56:39 volumio systemd[1]: mpd.service: Consumed 4.529s CPU time.
Dec 09 02:56:39 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 02:56:39 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:39 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 02:56:39 volumio volumio[762]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599459] CoreMusicLibrary::Adding element Last_100
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599464] CoreMusicLibrary::Adding element Webradio
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 02:56:39 volumio volumio[762]: info: Initializing BBC Radios
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599534] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:39 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599548] CoreMusicLibrary::Adding element SoundCloud
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:39 volumio volumio[762]: info: Creating Spotify config file
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:39 volumio sudo[1035]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 02:56:39 volumio sudo[1035]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 02:56:39 volumio sudo[1035]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:39 volumio volumio[762]: info: [squeezelite_mc] Starting proxy server...
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599929] CoreMusicLibrary::Adding element YouTube2
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source YouTube2
Dec 09 02:56:39 volumio volumio-remote-updater[9752]: [2025-12-09 02:56:39] [connect] Successful connection
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599951] CoreMusicLibrary::Adding element YouTube Music
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source YouTube2
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source YouTube Music
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:39 volumio volumio[762]: info: [1765270599966] CoreMusicLibrary::Adding element Podcast
Dec 09 02:56:39 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source YouTube2
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source YouTube Music
Dec 09 02:56:39 volumio volumio[762]: Cannot find translation for source Podcast
Dec 09 02:56:40 volumio volumio[762]: info: Loading i18n strings for locale en
Dec 09 02:56:40 volumio volumio[762]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 02:56:40 volumio volumio[762]: Updating browse sources language
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source YouTube2
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source YouTube Music
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source Podcast
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source YouTube2
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source YouTube Music
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source Podcast
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:40 volumio volumio[762]: info: [1765270600021] CoreMusicLibrary::Adding element Volusonic
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source YouTube2
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source YouTube Music
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source Podcast
Dec 09 02:56:40 volumio volumio[762]: Cannot find translation for source Volusonic
Dec 09 02:56:40 volumio volumio[762]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 09 02:56:40 volumio volumio[762]: info: Volumio Calling Home
Dec 09 02:56:40 volumio volumio[762]: info: [squeezelite_mc] Proxy server started on port 40259
Dec 09 02:56:40 volumio volumio[762]: info: Preparing to generate the ALSA configuration file
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 02:56:40 volumio volumio[762]: info: Discovery: this is already registered,  a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 02:56:40 volumio volumio[762]: info: Discovery: Found device Volumio
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:40 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:40 volumio volumio[762]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 02:56:40 volumio volumio[762]: info: Reading ALSA contributions from plugins.
Dec 09 02:56:40 volumio volumio[762]: info: MPD Permissions set
Dec 09 02:56:40 volumio volumio[762]: info: MPD Permissions set
Dec 09 02:56:40 volumio volumio[762]: info: Upmpdcli Daemon Started
Dec 09 02:56:40 volumio volumio-remote-updater[9752]: [2025-12-09 02:56:40] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765270599 101
Dec 09 02:56:40 volumio volumio[762]: 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 09 02:56:40 volumio volumio[762]: info: Spotify config file written
Dec 09 02:56:40 volumio sudo[1045]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 09 02:56:40 volumio sudo[1045]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:40 volumio volumio[762]: 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 09 02:56:40 volumio volumio[762]: info: VolumeController:: Volume=86 Mute =false
Dec 09 02:56:40 volumio volumio[762]: info: CoreStateMachine::pushState
Dec 09 02:56:40 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::volumioPushState
Dec 09 02:56:40 volumio volumio[762]: info: [squeezelite_mc] Server discovery started
Dec 09 02:56:40 volumio volumio[762]: info: [squeezelite_mc] Player finder started
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero  2>&1 || true
Dec 09 02:56:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:40 volumio go-librespot[1047]: go-librespot daemon starting...
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio sudo[1045]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-06:00" level=debug msg="app state loaded"
Dec 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:40 volumio volumio[762]: info: No need to fix Spotify hosts
Dec 09 02:56:40 volumio volumio[762]: 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 09 02:56:40 volumio volumio[762]: info: Volumio called home
Dec 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-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 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-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 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-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 09 02:56:40 volumio volumio[762]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 09 02:56:40 volumio volumio[762]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-06:00" level=info msg="zeroconf server listening on port 43727"
Dec 09 02:56:40 volumio volumio[762]: 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 09 02:56:40 volumio volumio[762]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 02:56:40 volumio volumio[762]: SPOTIFY: BQBatTWB_Ix0b4mehJYtZ9L3QrKkDirUg8tlRWIBj3RFr67LzIAtzPgOHEpzA6uXPzAqlmoG4mqCzEZWpdODdYKDifvDdbANWpcgE6YN0DEALrdwKS6mTwvilnCAitlaL08d8GeW4d9tkR_9PqfmmpYHijF_PGDu5njPANduMG93l10lya0MRFQyfkXqmLb6PGhxNBNbbionYRtn1xbsa8-XCzjZp5BQj_uOE8E
Dec 09 02:56:40 volumio volumio[762]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 02:56:40 volumio volumio[762]: info: New Spotify access token = BQBatTWB_Ix0b4mehJYtZ9L3QrKkDirUg8tlRWIBj3RFr67LzIAtzPgOHEpzA6uXPzAqlmoG4mqCzEZWpdODdYKDifvDdbANWpcgE6YN0DEALrdwKS6mTwvilnCAitlaL08d8GeW4d9tkR_9PqfmmpYHijF_PGDu5njPANduMG93l10lya0MRFQyfkXqmLb6PGhxNBNbbionYRtn1xbsa8-XCzjZp5BQj_uOE8E
Dec 09 02:56:40 volumio volumio[762]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 09 02:56:40 volumio volumio[762]: 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 09 02:56:40 volumio volumio[762]: info: Starting Shairport Sync
Dec 09 02:56:40 volumio volumio[762]: info: Starting Shairport Sync
Dec 09 02:56:40 volumio volumio[762]: info: Starting Shairport Sync
Dec 09 02:56:40 volumio go-librespot[1048]: time="2025-12-09T02:56:40-06:00" level=debug msg="obtained new client token: AAD7bZWyS5nF7aQ9Y9QWviJ7WLjv9+t2Ts24FSw2t9Vl2qp9k8GU+cbMPoglmW9w79mzN0qmHdXBguSyG6lln1TdpdjUzU57gkplJetnOngloZMRxYWogewGVMAw0IaKktuypg67LStw3W/vFz4/AORV66Vds9+EqCjx1uSXHxC3NXgJIjWbdYwV1shexG4Se6HBYtHEahJsuxYg2n8Sv6niBRbfAZCRfZFONrf3nZ4DHg4sZeC4+x+98A=="
Dec 09 02:56:41 volumio sudo[1076]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:41 volumio sudo[1076]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio sudo[1079]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:41 volumio sudo[1080]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:41 volumio sudo[1080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio go-librespot[1048]: time="2025-12-09T02:56:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:41 volumio sudo[1079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio sudo[1074]:  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 09 02:56:41 volumio volumio[762]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 02:56:41 volumio volumio[762]: info: Output device has changed, restarting MPD
Dec 09 02:56:41 volumio sudo[1074]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio go-librespot[1048]: time="2025-12-09T02:56:41-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:41 volumio go-librespot[1048]: time="2025-12-09T02:56:41-06:00" level=debug msg="completed challenge"
Dec 09 02:56:41 volumio volumio[762]: info: Output device has changed, restarting Shairport Sync
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:41 volumio sudo[1074]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 02:56:41 volumio sudo[1091]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 02:56:41 volumio go-librespot[1048]: time="2025-12-09T02:56:41-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 09 02:56:41 volumio volumio[762]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 02:56:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 02:56:41 volumio sudo[1091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:41 volumio systemd[1]: shairport-sync.service: Consumed 1.853s CPU time.
Dec 09 02:56:41 volumio sudo[1086]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 02:56:41 volumio sudo[1086]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio sudo[1086]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:41 volumio sudo[1079]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:41 volumio sudo[1076]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio sudo[1080]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 02:56:41 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 02:56:41 volumio systemd[1]: mpd.service: Consumed 1.604s CPU time.
Dec 09 02:56:41 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 02:56:41 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:41 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 02:56:41 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 02:56:41 volumio volumio[762]: info: MPD Permissions set
Dec 09 02:56:41 volumio volumio[762]: info: Shairport-Sync Started
Dec 09 02:56:41 volumio volumio[762]: Error adding Membership: Error: addMembership EINVAL
Dec 09 02:56:41 volumio volumio[762]: info: Shairport-Sync Started
Dec 09 02:56:41 volumio volumio[762]: info: Shairport-Sync Started
Dec 09 02:56:41 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 02:56:41 volumio volumio[762]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 09 02:56:41 volumio sudo[1121]:  volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 09 02:56:41 volumio sudo[1121]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio sudo[1121]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio volumio[762]: 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 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:41 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:41 volumio sudo[1118]:     root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 02:56:41 volumio sudo[1118]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 02:56:41 volumio sudo[1118]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio volumio[762]: info: Starting Shairport Sync
Dec 09 02:56:41 volumio sudo[1126]:  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 09 02:56:41 volumio sudo[1126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio sudo[1135]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 02:56:41 volumio sudo[1135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio sudo[1126]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload  || true
Dec 09 02:56:41 volumio volumio[762]: 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 09 02:56:41 volumio volumio[762]: info: Spotify Successfully logged in
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 02:56:41 volumio volumio[762]: info: [1765270601821] CoreMusicLibrary::Adding element Spotify
Dec 09 02:56:41 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 02:56:41 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 02:56:41 volumio volumio[762]: Cannot find translation for source Bandcamp Discover
Dec 09 02:56:41 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 02:56:41 volumio volumio[762]: Cannot find translation for source SoundCloud
Dec 09 02:56:41 volumio volumio[762]: Cannot find translation for source YouTube2
Dec 09 02:56:41 volumio volumio[762]: Cannot find translation for source YouTube Music
Dec 09 02:56:41 volumio volumio[762]: Cannot find translation for source Podcast
Dec 09 02:56:41 volumio volumio[762]: Cannot find translation for source Volusonic
Dec 09 02:56:41 volumio volumio[762]: Cannot find translation for source Spotify
Dec 09 02:56:41 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:41 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 02:56:41 volumio sudo[1135]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:41 volumio sudo[1139]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 09 02:56:41 volumio sudo[1139]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:41 volumio volumio[762]: info: Shairport-Sync Started
Dec 09 02:56:41 volumio systemd[1]: Reloading.
Dec 09 02:56:42 volumio volumio[762]: info: [squeezelite_mc] Notification listener started
Dec 09 02:56:42 volumio volumio[762]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 02:56:42 volumio volumio[762]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"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"}},{"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 09 02:56:42 volumio volumio[762]: 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 09 02:56:42 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:42 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:42 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:56:42 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 02:56:43 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 09 02:56:43 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 09 02:56:43 volumio sudo[1139]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:43 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:43 volumio volumio[762]: info: go-librespot daemon successfully initialized
Dec 09 02:56:43 volumio sudo[1178]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:43 volumio sudo[1178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:44 volumio volumio[762]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:44 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:44 volumio sudo[1178]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:44 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 09 02:56:44 volumio sudo[1181]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 09 02:56:44 volumio sudo[1181]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:44 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 02:56:44 volumio volumio[762]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 09 02:56:44 volumio volumio[762]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:44 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10.
Dec 09 02:56:44 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 09 02:56:44 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 02:56:44 volumio sudo[1181]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:44 volumio go-librespot[1183]: go-librespot daemon starting...
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-06:00" level=debug msg="app state loaded"
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-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 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-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 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-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 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-06:00" level=info msg="zeroconf server listening on port 35445"
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-06:00" level=debug msg="obtained new client token: AADDcTB2/TDMPcBt1HkJb8Qymj5qSZIsnxf1gx/KnRz8acdy6z8qZywusxRIQmPvXBKsUIhi7+vyOHSTWQYHlKyy8fdHz1ZA9eYu3JNhkyEc4oLxAfWWZ/Usx11VpzhAjYkb+eMHSF4EYWwuLfxZT7pjjmTrhus7r2fzmERLwATsQSEHZpMt9t9VrJ7MgXsxwKvAX1a8OCCfSPGYfApVXCjcIRSTRZtJngH1sMiv/att91RQM292FXXlDw=="
Dec 09 02:56:44 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-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 09 02:56:44 volumio sudo[1192]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:44 volumio sudo[1192]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:44 volumio go-librespot[1184]: time="2025-12-09T02:56:44-06:00" level=debug msg="connected to ap-guc3.spotify.com:443"
Dec 09 02:56:45 volumio sudo[1192]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:45 volumio volumio[762]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 09 02:56:45 volumio go-librespot[1184]: time="2025-12-09T02:56:45-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:45 volumio go-librespot[1184]: time="2025-12-09T02:56:45-06:00" level=debug msg="completed challenge"
Dec 09 02:56:45 volumio sudo[1196]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 09 02:56:45 volumio sudo[1196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:45 volumio sudo[1196]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:45 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 09 02:56:45 volumio go-librespot[1184]: time="2025-12-09T02:56:45-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 09 02:56:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:45 volumio sudo[1199]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 09 02:56:45 volumio sudo[1199]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:45 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 02:56:45 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 02:56:45 volumio sudo[1199]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:45 volumio volumio[762]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 09 02:56:45 volumio volumio[762]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 02:56:45 volumio volumio[762]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"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"}},{"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 09 02:56:45 volumio volumio[762]: 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 09 02:56:45 volumio mpd[1133]: 2025-12-09T02:56:45 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 09 02:56:45 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 09 02:56:45 volumio sudo[991]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:45 volumio sudo[1009]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:45 volumio sudo[1091]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:45 volumio volumio[762]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 02:56:45 volumio volumio[762]:   assert.ok(self.idling)
Dec 09 02:56:45 volumio volumio[762]: error: The expression evaluated to a falsy value:
Dec 09 02:56:45 volumio volumio[762]:   assert.ok(self.idling)
Dec 09 02:56:45 volumio volumio[762]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 02:56:45 volumio volumio[762]:   assert.ok(self.idling)
Dec 09 02:56:45 volumio volumio[762]: error: The expression evaluated to a falsy value:
Dec 09 02:56:45 volumio volumio[762]:   assert.ok(self.idling)
Dec 09 02:56:45 volumio volumio[762]: info: MPD running with PID1133
Dec 09 02:56:45 volumio volumio[762]:  ,establishing connection
Dec 09 02:56:45 volumio volumio[762]: error: updateQueue error: null
Dec 09 02:56:45 volumio volumio[762]: error: updateQueue error: null
Dec 09 02:56:45 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:45 volumio sudo[1210]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:45 volumio sudo[1210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:45 volumio sudo[1210]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:46 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:46 volumio sudo[1213]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:46 volumio sudo[1213]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:46 volumio sudo[1213]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:46 volumio volumio[762]: info: CoreCommandRouter::volumioGetState
Dec 09 02:56:46 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:56:46 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:46 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:56:47 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:47 volumio sudo[1231]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:47 volumio sudo[1231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:47 volumio sudo[1231]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:47 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:47 volumio sudo[1234]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:47 volumio sudo[1234]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:47 volumio sudo[1234]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11.
Dec 09 02:56:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:48 volumio volumio[762]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 02:56:48 volumio sudo[1238]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 02:56:48 volumio sudo[1238]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:48 volumio go-librespot[1236]: go-librespot daemon starting...
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=debug msg="app state loaded"
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:48 volumio sudo[1238]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:48 volumio volumio[762]: info: Completed starting Core Plugins
Dec 09 02:56:48 volumio volumio[762]: info: -------------------------------------------
Dec 09 02:56:48 volumio volumio[762]: info: -----    MyVolumio plugins startup     ----
Dec 09 02:56:48 volumio volumio[762]: info: -------------------------------------------
Dec 09 02:56:48 volumio volumio[762]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-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 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-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 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-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 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=info msg="zeroconf server listening on port 35671"
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=debug msg="obtained new client token: AABEHOtBdJcbuGRhumJgN9MFUAsyyiI79JYTUvz0fopEQJUVkLid7jupMxLa+m39YjdjL86067zQ6NzcDyenTEI3Pxm3AfHerMJ7xLj/MTTYnq1tBZclt44WYBvpUqwOMP2j3CX4YMy9NOvmaP9sx3DPmGTOHqbzfY6WmylavCNvAjKKqgBFNTM0mxksLSia06Rifv8Z1IEOFGGL7zhdkQk+ZQkIW3u6w8bdnzt7v9CaY+DuglfvPnhvcw=="
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:48 volumio sudo[1248]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 02:56:48 volumio sudo[1248]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-06:00" level=debug msg="completed challenge"
Dec 09 02:56:48 volumio sudo[1250]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 02:56:48 volumio sudo[1252]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 02:56:48 volumio sudo[1250]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:48 volumio sudo[1252]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:48 volumio go-librespot[1240]: time="2025-12-09T02:56:48-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 09 02:56:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:48 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 09 02:56:48 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 09 02:56:48 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 09 02:56:48 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 09 02:56:48 volumio sudo[1250]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:48 volumio mpd_monitor.sh[1256]: MPD Monitor Service: Starting MPD Monitor Service
Dec 09 02:56:48 volumio sudo[1248]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:48 volumio volumio[762]: info: Successfully started MPD Monitor
Dec 09 02:56:48 volumio sudo[1252]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:48 volumio volumio[762]: info: Successfully started MPD Monitor
Dec 09 02:56:48 volumio volumio[762]: info: Successfully started MPD Monitor
Dec 09 02:56:49 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:49 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:56:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12.
Dec 09 02:56:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:51 volumio go-librespot[1261]: go-librespot daemon starting...
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=debug msg="app state loaded"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-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 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-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 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-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 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=info msg="zeroconf server listening on port 37763"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=debug msg="obtained new client token: AABcofp+8CrCIJcmRcaKVR9Vs/sDostVOrWzPDKyLNBWiRZqSZjP3EUNkpp12OODXBNuwPf4b3wg0TZOHEIq3VDwlAN/tnSN5w7k2g2lsIfeSsZQhx3KaZOUul262S9lJ+9LjVaBM0DCze09M0xuF0hw4V1sXy/HSHlCstgubGi5dOBTJzCi/knYQTSCmqbjXTxC1MldtOT9uGJXcAJw4VainxRVUbVU5INJ1Bo8GFavVMDSETrroC2hmQ=="
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-06:00" level=debug msg="completed challenge"
Dec 09 02:56:52 volumio go-librespot[1262]: time="2025-12-09T02:56:52-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 09 02:56:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:53 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:53 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:56:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13.
Dec 09 02:56:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:55 volumio go-librespot[1270]: go-librespot daemon starting...
Dec 09 02:56:55 volumio go-librespot[1271]: time="2025-12-09T02:56:55-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:55 volumio go-librespot[1271]: time="2025-12-09T02:56:55-06:00" level=debug msg="app state loaded"
Dec 09 02:56:55 volumio go-librespot[1271]: time="2025-12-09T02:56:55-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:55 volumio go-librespot[1271]: time="2025-12-09T02:56:55-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:55 volumio go-librespot[1271]: time="2025-12-09T02:56:55-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 09 02:56:55 volumio go-librespot[1271]: time="2025-12-09T02:56:55-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 09 02:56:56 volumio go-librespot[1271]: time="2025-12-09T02:56:55-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 09 02:56:56 volumio go-librespot[1271]: time="2025-12-09T02:56:56-06:00" level=info msg="zeroconf server listening on port 38799"
Dec 09 02:56:56 volumio go-librespot[1271]: time="2025-12-09T02:56:56-06:00" level=debug msg="obtained new client token: AAAFEtqyhI8qdH/xoJmDbluqjQ6tFokoPmFrMyOUPUFasCVZSVyGe7ANuEfLDjHzC+++RxqYQagLx/n8gfXHG3Ieozlo+M5eL7YuhxKRNORhQ+0LE9FmvRs0IAoA6bUCdyCqOZFBUj4HXy4sRB3wq/x3CxSgQBIX4ntOckT/SigUX0JionhYIvnhAluQc/aYqTRHJvbzPXez5a5/PcQqJBcPjpZTllQxjOwLIutoJEeBB0/wggXjWwA="
Dec 09 02:56:56 volumio go-librespot[1271]: time="2025-12-09T02:56:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:56 volumio go-librespot[1271]: time="2025-12-09T02:56:56-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:56 volumio go-librespot[1271]: time="2025-12-09T02:56:56-06:00" level=debug msg="completed challenge"
Dec 09 02:56:56 volumio go-librespot[1271]: time="2025-12-09T02:56:56-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 09 02:56:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:56:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:56:56 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:56 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 09 02:56:56 volumio volumio[762]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 09 02:56:56 volumio volumio[762]: info: Adding plugin multiroom to MyMusic Plugins
Dec 09 02:56:56 volumio volumio[762]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 09 02:56:56 volumio volumio[762]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 09 02:56:56 volumio volumio[762]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 09 02:56:56 volumio volumio[762]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 09 02:56:56 volumio volumio[762]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 09 02:56:56 volumio volumio[762]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 09 02:56:57 volumio volumio[762]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 09 02:56:57 volumio volumio[762]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 09 02:56:57 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:57 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:56:57 volumio volumio[762]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 09 02:56:57 volumio volumio[762]: info: MyVolumio login type: Token
Dec 09 02:56:57 volumio volumio[762]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 09 02:56:57 volumio volumio[762]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 09 02:56:58 volumio volumio[762]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 09 02:56:58 volumio volumio[762]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 09 02:56:58 volumio volumio[762]: info: Streaming services startup
Dec 09 02:56:58 volumio volumio[762]: info: Starting Streaming Daemon
Dec 09 02:56:58 volumio sudo[1293]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 02:56:58 volumio sudo[1293]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:58 volumio volumio[762]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 09 02:56:58 volumio sudo[1293]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:58 volumio volumio[762]: error: Cannot start Volumio Streaming Daemon
Dec 09 02:56:58 volumio volumio[762]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 02:56:58 volumio volumio[762]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 02:56:58 volumio volumio[762]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 09 02:56:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14.
Dec 09 02:56:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:59 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:56:59 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:56:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:56:59 volumio go-librespot[1299]: go-librespot daemon starting...
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=debug msg="app state loaded"
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=debug msg="stored credentials not found"
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:56:59 volumio volumio[762]: info: MyVolumio token set successfully
Dec 09 02:56:59 volumio volumio[762]: info: MYVOLUMIO: Adding device
Dec 09 02:56:59 volumio volumio[762]: info: MYVOLUMIO: Evaluating Server
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-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 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-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 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-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 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=info msg="zeroconf server listening on port 45875"
Dec 09 02:56:59 volumio volumio[762]: info: MyVolumio status changed
Dec 09 02:56:59 volumio volumio[762]: info: Streaming services startup
Dec 09 02:56:59 volumio volumio[762]: info: Starting Streaming Daemon
Dec 09 02:56:59 volumio volumio[762]: info: Removing browser output: myVolumio user plan is not superstar
Dec 09 02:56:59 volumio volumio[762]: info: Removing audio output:
Dec 09 02:56:59 volumio volumio[762]: info: Stoppping Tunnel 1
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=debug msg="obtained new client token: AABm+wWK2dVtlvpwJQDPxdbypt6o+kTrZwfZIFMu3EIR25ELdCIo+Wg8TA2g0Lmf/ljf309l2iYlHcMXEVE3eqIPzZJi+0MBt8hfUdKKPasoIX1rMtgKMvyGFytImDYNNJq1zxUHVITMTSHDLoF3TvNZEOqYHUeASiWhkB311K1OFIakzZgVe6tw/ltDO2hH1HDAjkRagbyy7Mwx+3MxhXfoOo8L8sua1+7f4kSK/FG5OxcHWxCeBay5oA=="
Dec 09 02:56:59 volumio sudo[1328]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 02:56:59 volumio sudo[1328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:59 volumio sudo[1330]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 09 02:56:59 volumio sudo[1330]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:56:59 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 09 02:56:59 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 09 02:56:59 volumio sudo[1328]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:59 volumio volumio[762]: error: Cannot start Volumio Streaming Daemon
Dec 09 02:56:59 volumio volumio[762]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 02:56:59 volumio volumio[762]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 02:56:59 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 09 02:56:59 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 09 02:56:59 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 09 02:56:59 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 09 02:56:59 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 09 02:56:59 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 09 02:56:59 volumio sudo[1330]: pam_unix(sudo:session): session closed for user root
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=debug msg="completed keyexchange"
Dec 09 02:56:59 volumio go-librespot[1300]: time="2025-12-09T02:56:59-06:00" level=debug msg="completed challenge"
Dec 09 02:56:59 volumio volumio[762]: info: Remote SSH Stopped
Dec 09 02:57:00 volumio go-librespot[1300]: time="2025-12-09T02:57:00-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 09 02:57:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:00 volumio volumio[762]: info: Setting Geolocation for MyVolumio to us4
Dec 09 02:57:00 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:00 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:00 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:00 volumio volumio[762]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 02:57:01 volumio volumio[762]: info: Updating MyVolumio device info
Dec 09 02:57:01 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:01 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:01 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:01 volumio volumio[762]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 02:57:02 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:02 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15.
Dec 09 02:57:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:03 volumio go-librespot[1333]: go-librespot daemon starting...
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=debug msg="app state loaded"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-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 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-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 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=info msg="zeroconf server listening on port 38373"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=debug msg="obtained new client token: AADAZZ0BJxzgFpWuZHl+3VvjQ9ouGyQITMbvkitReXIguLOpNlYlpi6XGmwGI0PpQ2/Oj+YTuddU6VpeB0ycxU6UKWTMjw9nv15xugjC5nbMFEeltu0ZN7KCJmgfbDatCVBq0eoR/VOjUDhczAC2TKtwK/U/9ESooG43FwcAeD25u7wfDBuAGmmwBq33n/vbAmfQRqGV5VFkygF6DzYQAEQxV4x2Od6tFazp0DgtKSYt6MH6XM0Ba2BGcw=="
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-06:00" level=debug msg="completed challenge"
Dec 09 02:57:03 volumio go-librespot[1334]: time="2025-12-09T02:57:03-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 09 02:57:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:04 volumio volumio[762]: info: MYVOLUMIO: Adding device
Dec 09 02:57:04 volumio volumio[762]: info: MYVOLUMIO: Evaluating Server
Dec 09 02:57:04 volumio volumio[762]: info: Setting Geolocation for MyVolumio to us1
Dec 09 02:57:04 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:04 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:04 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:05 volumio volumio[762]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 02:57:05 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:05 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:05 volumio volumio[762]: info: Updating MyVolumio device info
Dec 09 02:57:05 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:05 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:05 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:05 volumio volumio[762]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 02:57:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16.
Dec 09 02:57:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:06 volumio go-librespot[1359]: go-librespot daemon starting...
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="app state loaded"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=info msg="zeroconf server listening on port 36215"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="obtained new client token: AACTu6+S5Dm4kxNryJCOe0Vc3YNkxNJI93YaSdezjaTSc2OVdjRB5/1tCVJTevOy+SurcwqMEZtgnwZK73ONrXe0u0YmcWt/UWtjPo3z6P9hd5CLdFC3dlHJIqYZohYZqboBarwHEf8kzVk/X0F1O74Ly6i0TS0aRBlGkKeGpP6EaDTEn1F5uHYRvCaVZ1hJ7NKH4B5s3sXhrG6pyxcObNOzMzltBBfxBxmVjtIyeHWq1MLO2KbQoKb/Jg=="
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=debug msg="completed challenge"
Dec 09 02:57:07 volumio go-librespot[1360]: time="2025-12-09T02:57:07-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 02:57:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:08 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:08 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:09 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 02:57:09 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:09 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 09 02:57:10 volumio volumio-remote-updater[9752]: Test mode disabled
Dec 09 02:57:10 volumio volumio-remote-updater[9752]: Alpha mode disabled
Dec 09 02:57:10 volumio volumio-remote-updater[9752]: Alpha legacy test mode disabled
Dec 09 02:57:10 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 09 02:57:10 volumio volumio[762]: 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 09 02:57:10 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 09 02:57:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17.
Dec 09 02:57:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:10 volumio go-librespot[1388]: go-librespot daemon starting...
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57:10-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57:10-06:00" level=debug msg="app state loaded"
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57:10-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57:10-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57:10-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57:10-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 02:57:10 volumio go-librespot[1389]: time="2025-12-09T02:57:10-06:00" level=info msg="zeroconf server listening on port 39485"
Dec 09 02:57:11 volumio go-librespot[1389]: time="2025-12-09T02:57:11-06:00" level=debug msg="obtained new client token: AABh+DsVO9CMLazpIDLgBAI5/dqKN7cRq6L3ZOkrOdNYPPVun0f2lYdDtIabwvzl+8gN/jBUVUQ8KZhj6+A2pUPcs3M4LXa7/fNhIfm0VNYlw2/Tj73JsouomXDLYIlUBO5XcfS9Io9XO97LWprF1B8oU363LFoSglnm+5tlVxVTCKk42oNx5/sCl2i8fJomBiVb9uoFxcnAtaS44zp210vVPL7TsNlhADI7WN4vsw16vGKbLcszKRU="
Dec 09 02:57:11 volumio go-librespot[1389]: time="2025-12-09T02:57:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:57:11 volumio go-librespot[1389]: time="2025-12-09T02:57:11-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:11 volumio go-librespot[1389]: time="2025-12-09T02:57:11-06:00" level=debug msg="completed challenge"
Dec 09 02:57:11 volumio go-librespot[1389]: time="2025-12-09T02:57:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 02:57:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:11 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:11 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:12 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 09 02:57:12 volumio volumio[762]: 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 09 02:57:12 volumio volumio[762]: info: CoreCommandRouter::volumioGetState
Dec 09 02:57:12 volumio volumio[762]: info: CorePlayQueue::getTrack 0
Dec 09 02:57:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18.
Dec 09 02:57:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:14 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:14 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:14 volumio go-librespot[1398]: go-librespot daemon starting...
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=debug msg="app state loaded"
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57: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 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57: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 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57: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 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=info msg="zeroconf server listening on port 39425"
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=debug msg="obtained new client token: AADkkND2AAk/EHmdDbRSV+Gu9WJOneJpoZCMh5Mo6uk6UOOTvpvigOC0pSy7n6gCNz10TUIWI0Gv9bWYW6qdbSEIl0QTSiu8B636KGAe3sBhVwC1HPjLdNzH1Frzcb84J+4BY7gFiGI8qLqu54QHJiAapqW7OUvL7c6znQHQqJtIK2lI3NoB7LsEhMV7K6gGy2PftVKPsRsvQHomPLLaLRF7fGmyyYvNY1G7tdOLVvMOfROZOQR9JKzOrg=="
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:14 volumio go-librespot[1399]: time="2025-12-09T02:57:14-06:00" level=debug msg="completed challenge"
Dec 09 02:57:15 volumio go-librespot[1399]: time="2025-12-09T02:57:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 02:57:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:17 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:17 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:17 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:57:17 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:57:17 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Dec 09 02:57:17 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 09 02:57:17 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Dec 09 02:57:17 volumio volumio[762]: info: CoreCommandRouter::volumioGetBrowseSources
Dec 09 02:57:17 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 02:57:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19.
Dec 09 02:57:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:18 volumio go-librespot[1420]: go-librespot daemon starting...
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=debug msg="app state loaded"
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57: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 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57: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 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57: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 09 02:57:18 volumio volumio[762]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Dec 09 02:57:18 volumio volumio[762]: info: Completed starting MyVolumio Plugin
Dec 09 02:57:18 volumio volumio[762]:  [Metrics]  CommandRouter:  53s 718.81ms 
Dec 09 02:57:18 volumio volumio[762]: info: CoreCommandRouter::volumiosetStartupVolume
Dec 09 02:57:18 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 02:57:18 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=info msg="zeroconf server listening on port 37353"
Dec 09 02:57:18 volumio volumio[762]: info: CoreCommandRouter::Close All Modals sent
Dec 09 02:57:18 volumio volumio[762]: info: CoreCommandRouter::Close All Modals sent
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=debug msg="obtained new client token: AABwlIXQrhRFVhaJ+bqJvPbunK2Nj2SC0cNGyH5gFhbtbUex37w7+M0lJXAPvsOMqFrMPNKbVz/7eNFP9pr/N002NMRwFmXeSpajD9y5TIVs3wfC2OR1HsS/AO53HYaQFnGDatx6cyCoowrWSfDU4gcWvsdWxRKbvj60vHWdgMkqp/mx5hEahMt1DaHmYzpfyoNwWSpPd1qAbUUj+zjeva83eSHhu7Yrq/xfyhwS4JPElEfedWgzfzy/yw=="
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-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 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=debug msg="connected to ap-guc3.spotify.com:443"
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57:18-06:00" level=debug msg="completed challenge"
Dec 09 02:57:18 volumio go-librespot[1421]: time="2025-12-09T02:57: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 09 02:57:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:19 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Dec 09 02:57:19 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Dec 09 02:57:19 volumio volumio[762]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Dec 09 02:57:20 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:20 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20.
Dec 09 02:57:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:21 volumio go-librespot[1435]: go-librespot daemon starting...
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=debug msg="app state loaded"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-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 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-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 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=info msg="zeroconf server listening on port 37273"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=debug msg="obtained new client token: AADc3GJHoFJ1zvyd5I1tCUbwFgrsd/RL89A0Qq/7I9wazylesHxEm1rePNwhcv4ypvIXD6I3FpydopF78vp27wx7F++F5TTxIVPAxrev9bnsy6R0i4kcCF7l5JvQXw/8PjcmY1e92fySFtvBBPdYnFRK7sw+JR+Slp0ByaZSoUVl9DgUVa6/EwgFgta5wcirDVqM9btS+yt72NNIx0ja3/tM4yXmDIciQPG91w9kOGHe6RCBbirVsHbg3w=="
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57:22-06:00" level=debug msg="completed challenge"
Dec 09 02:57:22 volumio go-librespot[1436]: time="2025-12-09T02:57: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 09 02:57:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:23 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:23 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:25 volumio volumio[762]: info: BOOT COMPLETED
Dec 09 02:57:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21.
Dec 09 02:57:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:25 volumio go-librespot[1443]: go-librespot daemon starting...
Dec 09 02:57:25 volumio go-librespot[1444]: time="2025-12-09T02:57:25-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:25 volumio go-librespot[1444]: time="2025-12-09T02:57:25-06:00" level=debug msg="app state loaded"
Dec 09 02:57:25 volumio go-librespot[1444]: time="2025-12-09T02:57:25-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:25 volumio go-librespot[1444]: time="2025-12-09T02:57:25-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-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 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-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 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-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 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-06:00" level=info msg="zeroconf server listening on port 41047"
Dec 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-06:00" level=debug msg="obtained new client token: AAAAs/KGoZeiTeHv/a6ZrlwIsBtXlIPmd57GtjPb+/CHlmjSDNDJpg5nf8QUEqYVBSrZ6x/jt+SqbCEky4v8nB8EZzlGwVKtnierpvpG4YRwgnXbs1OpdL5Tv9Dg27JeeQx5+J1MxYlnCxUlgfnPX9cV/QAM+tCEpW3dIz0Xx3cxqlsWtNMDZYenkmsH1C71e4E2a1KtoSQ8kZOHrYY+oXRDfPh9uzOyUTo3Jqi1JhGZ4PZUeCYYdhI="
Dec 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-06:00" level=debug msg="completed challenge"
Dec 09 02:57:26 volumio go-librespot[1444]: time="2025-12-09T02:57:26-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 09 02:57:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:26 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:26 volumio volumio[762]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22.
Dec 09 02:57:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:29 volumio go-librespot[1469]: go-librespot daemon starting...
Dec 09 02:57:29 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service...
Dec 09 02:57:29 volumio volumio[762]: info: Initializing connection to go-librespot Websocket
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=debug msg="app state loaded"
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=debug msg="new websocket client"
Dec 09 02:57:29 volumio volumio[762]: info: Connection to go-librespot Websocket established
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-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 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-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 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=info msg="zeroconf server listening on port 42667"
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=debug msg="obtained new client token: AADYB81Eip+k6yw0ygDOh0Ynhh3prkHEmaZ1VG4ZSjOKdDTkCrvkk33QV08RonoA/UUy4ukuoa/Kbm0QrQwc0kzTVhPT78kwcvfIFWn47rUYNhLge4yt0K2gDoY5ylU59FWBl3ZijIH6xcGvZoBzppTT27sUZ+wkjMZoUXI3pTDXDYblOXF2+In4L6/XsVXaLXlW28amzBmkdmjOh3wRug7Zd7b+rmG3e+Nfag5XP89IaOAmq46a7433ZQ=="
Dec 09 02:57:29 volumio go-librespot[1471]: time="2025-12-09T02:57:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 02:57:30 volumio go-librespot[1471]: time="2025-12-09T02:57:30-06:00" level=debug msg="completed keyexchange"
Dec 09 02:57:30 volumio go-librespot[1471]: time="2025-12-09T02:57:30-06:00" level=debug msg="completed challenge"
Dec 09 02:57:30 volumio go-librespot[1471]: time="2025-12-09T02:57:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 02:57:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 02:57:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 02:57:30 volumio volumio[762]: info: Connection to go-librespot Websocket closed
Dec 09 02:57:30 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully.
Dec 09 02:57:30 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service.
Dec 09 02:57:32 volumio volumio[762]: info: Getting Spotify volume
Dec 09 02:57:32 volumio volumio[762]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 02:57:32 volumio volumio[762]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 02:57:32 volumio volumio[762]:     at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 09 02:57:32 volumio volumio[762]:   errno: -111,
Dec 09 02:57:32 volumio volumio[762]:   code: 'ECONNREFUSED',
Dec 09 02:57:32 volumio volumio[762]:   syscall: 'connect',
Dec 09 02:57:32 volumio volumio[762]:   address: '127.0.0.1',
Dec 09 02:57:32 volumio volumio[762]:   port: 9879,
Dec 09 02:57:32 volumio volumio[762]:   response: undefined
Dec 09 02:57:32 volumio volumio[762]: }
Dec 09 02:57:32 volumio volumio[762]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 02:57:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23.
Dec 09 02:57:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 02:57:33 volumio go-librespot[1521]: go-librespot daemon starting...
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=debug msg="app state loaded"
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=debug msg="stored credentials not found"
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 02:57:33 volumio sudo[1531]:  volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 02:56'
Dec 09 02:57:33 volumio sudo[1531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 02:57:33 volumio go-librespot[1522]: time="2025-12-09T02:57:33-06:00" level=info msg="zeroconf server listening on port 35841"
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"