Dec 08 09:49:00 volumio volumio[17013]: 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 08 09:49:00 volumio volumio[17013]: 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 08 09:49:00 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:00 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:00 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:00 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:49:01 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 08 09:49:01 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 08 09:49:01 volumio volumio[17013]: info: go-librespot daemon successfully initialized
Dec 08 09:49:01 volumio sudo[17345]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:01 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 08 09:49:01 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 08 09:49:01 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:01 volumio systemd[1]: shairport-sync.service: Consumed 1.509s CPU time.
Dec 08 09:49:01 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:01 volumio sudo[17371]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:01 volumio volumio[17013]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:01 volumio volumio[17013]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:01 volumio sudo[17371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:01 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:01 volumio sudo[17347]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:01 volumio volumio[17013]: info: Shairport-Sync Started
Dec 08 09:49:01 volumio sudo[17371]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:01 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 08 09:49:01 volumio sudo[17387]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 08 09:49:01 volumio sudo[17387]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:01 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 08 09:49:02 volumio volumio[17013]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 08 09:49:02 volumio volumio[17013]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:02 volumio volumio[17013]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21.
Dec 08 09:49:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:02 volumio go-librespot[17390]: go-librespot daemon starting...
Dec 08 09:49:02 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 08 09:49:02 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=debug msg="app state loaded"
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:02 volumio sudo[17387]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-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 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-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 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-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 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=info msg="zeroconf server listening on port 42027"
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=debug msg="obtained new client token: AAAzz/6Ve0jST53Zs1dOh+vdfJa+mzDPy2Y5Louvn3c6G5uc4ePYZEsG1bjtdjjRmqr9CUyLKxN3Aw76DldjFg5CQ7TARD78XzB8r84eukknLoh5YUUfImLfNOlL/8ScuMqlG6a1vdKPycPVhXg8b18MUKR4penNHvs3pNv0tsLf0zY1LuOulsfw9c1oj4xMjv9vCe5QSM2jlQKzDIHppComG8fNVXJc/pRQvJi3lv5YIyk4GrS/fMIVYg=="
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:02 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=debug msg="completed challenge"
Dec 08 09:49:02 volumio sudo[17400]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:02 volumio sudo[17400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:02 volumio go-librespot[17391]: time="2025-12-08T09:49:02-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:49:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:02 volumio sudo[17400]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:02 volumio volumio[17013]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 08 09:49:03 volumio sudo[17404]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 08 09:49:03 volumio sudo[17404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:03 volumio sudo[17404]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:03 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 08 09:49:03 volumio sudo[17407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 08 09:49:03 volumio sudo[17407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:03 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 08 09:49:03 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 08 09:49:03 volumio sudo[17407]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:03 volumio mpd[17350]: 2025-12-08T09:49:03 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 08 09:49:03 volumio volumio[17013]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 08 09:49:03 volumio volumio[17013]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 08 09:49:03 volumio volumio[17013]: 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 08 09:49:03 volumio volumio[17013]: 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 08 09:49:03 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 08 09:49:03 volumio sudo[17217]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:03 volumio sudo[17227]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:03 volumio sudo[17305]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:03 volumio volumio[17013]: error: MPD error: The expression evaluated to a falsy value:
Dec 08 09:49:03 volumio volumio[17013]: assert.ok(self.idling)
Dec 08 09:49:03 volumio volumio[17013]: error: The expression evaluated to a falsy value:
Dec 08 09:49:03 volumio volumio[17013]: assert.ok(self.idling)
Dec 08 09:49:03 volumio volumio[17013]: error: MPD error: The expression evaluated to a falsy value:
Dec 08 09:49:03 volumio volumio[17013]: assert.ok(self.idling)
Dec 08 09:49:03 volumio volumio[17013]: error: The expression evaluated to a falsy value:
Dec 08 09:49:03 volumio volumio[17013]: assert.ok(self.idling)
Dec 08 09:49:03 volumio volumio[17013]: error: updateQueue error: null
Dec 08 09:49:03 volumio volumio[17013]: info: MPD running with PID17350
Dec 08 09:49:03 volumio volumio[17013]: ,establishing connection
Dec 08 09:49:03 volumio volumio[17013]: error: updateQueue error: null
Dec 08 09:49:03 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:03 volumio sudo[17418]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:03 volumio sudo[17418]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:03 volumio sudo[17418]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:04 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:04 volumio sudo[17421]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:04 volumio sudo[17421]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:04 volumio sudo[17421]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:04 volumio volumio[17013]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:04 volumio volumio[17013]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:04 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:04 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:04 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:04 volumio sudo[17438]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:04 volumio sudo[17438]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:04 volumio sudo[17438]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:05 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:05 volumio sudo[17444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:05 volumio sudo[17444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:05 volumio sudo[17444]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22.
Dec 08 09:49:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:06 volumio go-librespot[17446]: go-librespot daemon starting...
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=debug msg="app state loaded"
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:06 volumio volumio[17013]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:06 volumio sudo[17454]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:06 volumio sudo[17454]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:06 volumio sudo[17454]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:06 volumio volumio[17013]: info: Completed starting Core Plugins
Dec 08 09:49:06 volumio volumio[17013]: info: -------------------------------------------
Dec 08 09:49:06 volumio volumio[17013]: info: ----- MyVolumio plugins startup ----
Dec 08 09:49:06 volumio volumio[17013]: info: -------------------------------------------
Dec 08 09:49:06 volumio volumio[17013]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-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 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-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 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-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 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=info msg="zeroconf server listening on port 46223"
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=debug msg="obtained new client token: AACvJ6JwvSdlgJU7JL5/CumlNchDWTGsMGokHO79Sfe8CTb6V2W6FtezvPdg7d/v6ahUi37d1KDcDc/NzZytpnsXD6Is60Gd4ClT0UnDHk4Qo4YayC3C+uJ2l5i8tiq69Eh1XrsT7bdXBiWChg1PCkI+6E7f9fTpaBLbvosguE5NJxct6L+BZ48CPPZNdbHacF0WTmLe9w5d5fMSBWG7fJwSCTbeZi+wQFqk7WKWqQ2oXBaKKu+SqJtBQg=="
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-06:00" level=debug msg="completed challenge"
Dec 08 09:49:06 volumio sudo[17459]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:49:06 volumio sudo[17459]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:06 volumio sudo[17461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:49:06 volumio sudo[17461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:06 volumio sudo[17463]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:49:06 volumio sudo[17463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:06 volumio go-librespot[17447]: time="2025-12-08T09:49:06-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 08 09:49:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:06 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 08 09:49:06 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 08 09:49:06 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 08 09:49:06 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 08 09:49:06 volumio sudo[17463]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:06 volumio sudo[17459]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:06 volumio mpd_monitor.sh[17467]: MPD Monitor Service: Starting MPD Monitor Service
Dec 08 09:49:06 volumio sudo[17461]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:06 volumio volumio[17013]: info: Successfully started MPD Monitor
Dec 08 09:49:06 volumio volumio[17013]: info: Successfully started MPD Monitor
Dec 08 09:49:06 volumio volumio[17013]: info: Successfully started MPD Monitor
Dec 08 09:49:07 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:07 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23.
Dec 08 09:49:09 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:09 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:09 volumio go-librespot[17472]: go-librespot daemon starting...
Dec 08 09:49:09 volumio go-librespot[17473]: time="2025-12-08T09:49:09-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:09 volumio go-librespot[17473]: time="2025-12-08T09:49:09-06:00" level=debug msg="app state loaded"
Dec 08 09:49:09 volumio go-librespot[17473]: time="2025-12-08T09:49:09-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:09 volumio go-librespot[17473]: time="2025-12-08T09:49:09-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49: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-gew4.spotify.com:80]"
Dec 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-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 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-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 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-06:00" level=info msg="zeroconf server listening on port 44653"
Dec 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-06:00" level=debug msg="obtained new client token: AADEepcu7JNGT//f3wfkJtY2UblxUNlZUAlnJL7OpoU8DcmLdSDDZZnR1dSBCWusXw6tHAgT5eeEXhY9PpL4/lp9e/iZVkUzwrURdyvniAqr+EWAU2Pb8podJCIGRTbH3jcZnVehxc2mz1TPsJgNjpYYFkgqel3fZE/F3tRI8wBcgZXFE5e0eFJ8ihsQsWm/gzeHwYVuQp+eczIzRo/EBADvtaNmsJS9O8JJFax1cv3ujx4vpm8b5v4P3g=="
Dec 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-06:00" level=debug msg="completed challenge"
Dec 08 09:49:10 volumio go-librespot[17473]: time="2025-12-08T09:49:10-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:49:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:11 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:11 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24.
Dec 08 09:49:13 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:13 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:13 volumio go-librespot[17480]: go-librespot daemon starting...
Dec 08 09:49:13 volumio go-librespot[17481]: time="2025-12-08T09:49:13-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:13 volumio go-librespot[17481]: time="2025-12-08T09:49:13-06:00" level=debug msg="app state loaded"
Dec 08 09:49:13 volumio go-librespot[17481]: time="2025-12-08T09:49:13-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:13 volumio go-librespot[17481]: time="2025-12-08T09:49:13-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49: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 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49: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 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49: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 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49:14-06:00" level=info msg="zeroconf server listening on port 40911"
Dec 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49:14-06:00" level=debug msg="obtained new client token: AAAWWAGtAbjbn6kb+w4meXQh9D7IpyZljX2APHFOGkdibILL8lPOQ7FrAcu+9HXzrWJnGayE5ijbeLjvAbE4KnWb96ESODL1JSh7NMOUOtkPKx2DDcTTiYc2tlyAFC1NW3EA5m//D9aNw5ExvDa+TAGIPeh492KkmFzfOZZoMRV0FXRaJ4M6ZHiCrBEASSiq26Ow/MfDTaikoQt7gX5Co9FCZIGozghXVEqukBxG2WGBvl0NORWyhuQ="
Dec 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49:14-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49:14-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49:14-06:00" level=debug msg="completed challenge"
Dec 08 09:49:14 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:14 volumio go-librespot[17481]: time="2025-12-08T09:49: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 08 09:49:14 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: read ECONNRESET
Dec 08 09:49:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 08 09:49:14 volumio volumio[17013]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 08 09:49:14 volumio volumio[17013]: info: Adding plugin multiroom to MyMusic Plugins
Dec 08 09:49:14 volumio volumio[17013]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 08 09:49:14 volumio volumio[17013]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 08 09:49:14 volumio volumio[17013]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 08 09:49:14 volumio volumio[17013]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 08 09:49:14 volumio volumio[17013]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 08 09:49:14 volumio volumio[17013]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 08 09:49:15 volumio volumio[17013]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 08 09:49:15 volumio volumio[17013]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 08 09:49:15 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:15 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:15 volumio volumio[17013]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 08 09:49:15 volumio volumio[17013]: info: MyVolumio login type: Token
Dec 08 09:49:15 volumio volumio[17013]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 08 09:49:15 volumio volumio[17013]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 08 09:49:16 volumio volumio[17013]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 08 09:49:16 volumio volumio[17013]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 08 09:49:16 volumio volumio[17013]: info: Streaming services startup
Dec 08 09:49:16 volumio volumio[17013]: info: Starting Streaming Daemon
Dec 08 09:49:16 volumio sudo[17503]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 08 09:49:16 volumio sudo[17503]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:16 volumio volumio[17013]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 08 09:49:16 volumio sudo[17503]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:16 volumio volumio[17013]: error: Cannot start Volumio Streaming Daemon
Dec 08 09:49:16 volumio volumio[17013]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 08 09:49:16 volumio volumio[17013]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 08 09:49:16 volumio volumio[17013]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 08 09:49:17 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:17 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25.
Dec 08 09:49:17 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:17 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:17 volumio go-librespot[17510]: go-librespot daemon starting...
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=debug msg="app state loaded"
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-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 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-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 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-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 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=info msg="zeroconf server listening on port 41337"
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=debug msg="obtained new client token: AABQNGR5ecJQxN+srkFTdMqR4gKeSE193rwqOTSPzL6MbcmJiMItfxcjjQARPYB0/+GsaMfdLbgfv2r9jlHE0jFWDajp79hvgjBI+6nnaCdYISxGKSogjUlCAf0ELo+eBk293VOuKPa+A7Cme/3pK6bxTwLBJwYe5XnSHlgOEfEWulGzOw472gAFSXzcpmdyf0y8/+oD2gG1PeTR5znmxkBUl28hrpsV4ZO13e9wg1IdvM0rkNfFaGGykg=="
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:17 volumio go-librespot[17511]: time="2025-12-08T09:49:17-06:00" level=debug msg="completed challenge"
Dec 08 09:49:18 volumio go-librespot[17511]: time="2025-12-08T09:49: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 08 09:49:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:18 volumio volumio[17013]: info: MyVolumio token set successfully
Dec 08 09:49:18 volumio volumio[17013]: info: MYVOLUMIO: Adding device
Dec 08 09:49:18 volumio volumio[17013]: info: MYVOLUMIO: Evaluating Server
Dec 08 09:49:18 volumio volumio[17013]: info: MyVolumio status changed
Dec 08 09:49:18 volumio volumio[17013]: info: Streaming services startup
Dec 08 09:49:18 volumio volumio[17013]: info: Starting Streaming Daemon
Dec 08 09:49:18 volumio volumio[17013]: info: Removing browser output: myVolumio user plan is not superstar
Dec 08 09:49:18 volumio volumio[17013]: info: Removing audio output:
Dec 08 09:49:18 volumio volumio[17013]: info: Stoppping Tunnel 1
Dec 08 09:49:18 volumio sudo[17539]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 08 09:49:18 volumio sudo[17539]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:18 volumio sudo[17541]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 08 09:49:18 volumio sudo[17541]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 08 09:49:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 08 09:49:18 volumio sudo[17539]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:18 volumio volumio[17013]: error: Cannot start Volumio Streaming Daemon
Dec 08 09:49:18 volumio volumio[17013]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 08 09:49:18 volumio volumio[17013]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 08 09:49:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 08 09:49:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 08 09:49:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 08 09:49:18 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 08 09:49:18 volumio sudo[17541]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:18 volumio volumio[17013]: info: Remote SSH Stopped
Dec 08 09:49:18 volumio volumio[17013]: info: Setting Geolocation for MyVolumio to us1
Dec 08 09:49:18 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:18 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:18 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:19 volumio volumio[17013]: info: Updating MyVolumio device info
Dec 08 09:49:19 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:19 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:19 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:19 volumio volumio[17013]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 08 09:49:20 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:20 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:20 volumio volumio[17013]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 08 09:49:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26.
Dec 08 09:49:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:21 volumio go-librespot[17544]: go-librespot daemon starting...
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=debug msg="app state loaded"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-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 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-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 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=info msg="zeroconf server listening on port 42911"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=debug msg="obtained new client token: AACVfh38ETszLC3ydUT6R/XZ1lD1v/l7QNQeUconrevQAf+oivBz3PpM5s7dcHkCMRb2eHAuupD3qgZmUHB/mmCoMBBhusDv/lvx2a0veppsWNzn4Ww0kezZNE9ZbGYM5choMV3tqxR6Dheq44xiG6rHUlmAFUTrEa1dTZ7uCEAqX9FBNgTqYDubqf8UZF+Ad9qAKr2HtxGr2hNb23Q+w22Lxz0VBHunz1MIXwNwSeikwLWBD8LhxSjUAg=="
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-06:00" level=debug msg="completed challenge"
Dec 08 09:49:21 volumio go-librespot[17545]: time="2025-12-08T09:49:21-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 08 09:49:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:23 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:23 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:23 volumio volumio[17013]: info: MYVOLUMIO: Adding device
Dec 08 09:49:23 volumio volumio[17013]: info: MYVOLUMIO: Evaluating Server
Dec 08 09:49:24 volumio volumio[17013]: info: Setting Geolocation for MyVolumio to us4
Dec 08 09:49:24 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:24 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:24 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27.
Dec 08 09:49:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:25 volumio go-librespot[17584]: go-librespot daemon starting...
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=debug msg="app state loaded"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:25 volumio volumio[17013]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 08 09:49:25 volumio volumio[17013]: info: Updating MyVolumio device info
Dec 08 09:49:25 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:25 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:25 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-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 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-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 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=info msg="zeroconf server listening on port 39611"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=debug msg="obtained new client token: AACCjs5LFCnCOAXXcusge2EcZ/EuJu4O/mSwUd27qi3cQ06X7LQrExevzzwg35ckMJZKvw6H45mzvhwNX+Sz482LUChlFc56xMweckqOawAdLJegodHxTo69+BtJAhP8ZQPn/3FmfDjYogaExVxqrkKjjruEpK1kQl2OoYzVvkhCfDcKlmZHKlMm9XXWAPDgh8LDWHvBKpnN4OJS2AlVto4Sybzrb4xb2zaE5gkRhRZlFub7QkVSJXcCgQ=="
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=debug msg="completed challenge"
Dec 08 09:49:25 volumio go-librespot[17585]: time="2025-12-08T09:49:25-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:49:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:26 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:26 volumio volumio[17013]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:27 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 08 09:49:27 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:27 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 08 09:49:27 volumio volumio-remote-updater[9752]: Test mode disabled
Dec 08 09:49:27 volumio volumio-remote-updater[9752]: Alpha mode disabled
Dec 08 09:49:27 volumio volumio-remote-updater[9752]: Alpha legacy test mode disabled
Dec 08 09:49:27 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 08 09:49:27 volumio volumio[17013]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"ANNOUNCEMENT
\n\n- Production line
\n
\nFIX
\n\n- Nodejs 20.5.1 version pinning with static package fallback
\n
\n","title":"Update v4.073","updateavailable":true}
Dec 08 09:49:28 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 08 09:49:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28.
Dec 08 09:49:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:28 volumio go-librespot[17599]: go-librespot daemon starting...
Dec 08 09:49:28 volumio go-librespot[17600]: time="2025-12-08T09:49:28-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:28 volumio go-librespot[17600]: time="2025-12-08T09:49:28-06:00" level=debug msg="app state loaded"
Dec 08 09:49:28 volumio go-librespot[17600]: time="2025-12-08T09:49:28-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:28 volumio go-librespot[17600]: time="2025-12-08T09:49:28-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49: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 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49: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 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49: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 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49:29-06:00" level=info msg="zeroconf server listening on port 44531"
Dec 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49:29-06:00" level=debug msg="obtained new client token: AABAZMWbGdq3frvfiMOO0d1qzS7pWRfV/Hr3i4pKYVc7tshOTf5TfxKOLJylO35Axi1Lc+OYksSHIh+DIsxfhMWNmbHs5e2l01YTLbj/Y+wKg2OewCJfaiaIfmCS0poVTynN5f4ajwRbRiqgMFX/bGzsrVMJ4xlDVARqdJys+pL3RzRcizZqacHjkG83SUGmZwiu0ANGSwp0UCmWjwVhSV5fX/w2bKI+w5ZwfksPomxVrP3PYZSpP/I="
Dec 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49:29-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49:29-06:00" level=debug msg="completed challenge"
Dec 08 09:49:29 volumio volumio[17013]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49:29-06:00" level=debug msg="new websocket client"
Dec 08 09:49:29 volumio volumio[17013]: info: Connection to go-librespot Websocket established
Dec 08 09:49:29 volumio go-librespot[17600]: time="2025-12-08T09:49:29-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:49:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:29 volumio volumio[17013]: info: Connection to go-librespot Websocket closed
Dec 08 09:49:30 volumio volumio[17013]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 08 09:49:30 volumio volumio[17013]: 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 08 09:49:30 volumio volumio[17013]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:30 volumio volumio[17013]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:32 volumio volumio[17013]: info: Getting Spotify volume
Dec 08 09:49:32 volumio volumio[17013]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 08 09:49:32 volumio volumio[17013]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:32 volumio volumio[17013]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 08 09:49:32 volumio volumio[17013]: errno: -111,
Dec 08 09:49:32 volumio volumio[17013]: code: 'ECONNREFUSED',
Dec 08 09:49:32 volumio volumio[17013]: syscall: 'connect',
Dec 08 09:49:32 volumio volumio[17013]: address: '127.0.0.1',
Dec 08 09:49:32 volumio volumio[17013]: port: 9879,
Dec 08 09:49:32 volumio volumio[17013]: response: undefined
Dec 08 09:49:32 volumio volumio[17013]: }
Dec 08 09:49:32 volumio volumio[17013]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 08 09:49:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29.
Dec 08 09:49:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:32 volumio go-librespot[17618]: go-librespot daemon starting...
Dec 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-06:00" level=debug msg="app state loaded"
Dec 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-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 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-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 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-06:00" level=info msg="zeroconf server listening on port 36801"
Dec 08 09:49:32 volumio go-librespot[17620]: time="2025-12-08T09:49:32-06:00" level=debug msg="obtained new client token: AACRABF08PfuNKODz0/7aPTEkL6Wi9A3/Rh+549l8758ETE0uMCQ402wAsMxg6HnlvAQTKNUSBoQUTPaBjJLEBdSYychZp/iMLmsxDCksL+UvngyzYITsusFPlYhBBeHe4iqeCS2Rf3qok4DnDVTcw9sLacDUkrCNZyoarv5fqDehva/b/BWTpzBIvw94NHZaJ160Oc3gU0+6TiiB/pRpd5nYAUaiF149qnLXazWKYnEGcyUajRie7ZbRQ=="
Dec 08 09:49:33 volumio go-librespot[17620]: time="2025-12-08T09:49:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:33 volumio go-librespot[17620]: time="2025-12-08T09:49:33-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:33 volumio go-librespot[17620]: time="2025-12-08T09:49:33-06:00" level=debug msg="completed challenge"
Dec 08 09:49:33 volumio go-librespot[17620]: time="2025-12-08T09:49:33-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:49:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:33 volumio sudo[17629]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 09:48'
Dec 08 09:49:33 volumio sudo[17629]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:33 volumio sudo[17629]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:33 volumio volumio-remote-updater[9752]: [2025-12-08 09:49:33] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 08 09:49:33 volumio volumio-remote-updater[9752]: [2025-12-08 09:49:33] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 08 09:49:33 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:33 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 08 09:49:33 volumio systemd[1]: volumio.service: Consumed 46.746s CPU time.
Dec 08 09:49:33 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 08 09:49:33 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 08 09:49:33 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 23145.
Dec 08 09:49:33 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 08 09:49:33 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 08 09:49:33 volumio systemd[1]: volumio.service: Consumed 46.746s CPU time.
Dec 08 09:49:33 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 08 09:49:33 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 08 09:49:35 volumio volumio[17641]: info: -------------------------------------------
Dec 08 09:49:35 volumio volumio[17641]: info: ----- Volumio3 ----
Dec 08 09:49:35 volumio volumio[17641]: info: -------------------------------------------
Dec 08 09:49:35 volumio volumio[17641]: info: ----- System startup ----
Dec 08 09:49:35 volumio volumio[17641]: info: -------------------------------------------
Dec 08 09:49:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30.
Dec 08 09:49:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:36 volumio go-librespot[17662]: go-librespot daemon starting...
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=debug msg="app state loaded"
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:36 volumio volumio[17641]: info: MYVOLUMIO Environment detected
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-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 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-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 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-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 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=info msg="zeroconf server listening on port 33913"
Dec 08 09:49:36 volumio volumio[17641]: info: Plugin folders cleanup
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning into folder /volumio/app/plugins/
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category audio_interface
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category miscellanea
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category music_service
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category plugins.json
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category system_controller
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category user_interface
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning into folder /data/plugins/
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category audio_interface
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category music_service
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category system_controller
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category system_hardware
Dec 08 09:49:36 volumio volumio[17641]: info: Scanning category user_interface
Dec 08 09:49:36 volumio volumio[17641]: info: Plugin folders cleanup completed
Dec 08 09:49:36 volumio volumio[17641]: info: -------------------------------------------
Dec 08 09:49:36 volumio volumio[17641]: info: ----- Core plugins startup ----
Dec 08 09:49:36 volumio volumio[17641]: info: -------------------------------------------
Dec 08 09:49:36 volumio volumio[17641]: info: Loading plugins from folder /volumio/app/plugins/
Dec 08 09:49:36 volumio volumio[17641]: info: Adding plugin upnp to MyMusic Plugins
Dec 08 09:49:36 volumio volumio[17641]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 08 09:49:36 volumio volumio[17641]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 08 09:49:36 volumio volumio[17641]: info: Loading plugins from folder /data/plugins/
Dec 08 09:49:36 volumio volumio[17641]: info: Loading plugin "system"...
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=debug msg="obtained new client token: AAA7DHfwCL7yySdtir8nEfzcBciP5zaN2RpvJ7U1uwYKat5e4d6ZznfzjGAGy+CDsnPQSiyfsIA7RhEmnvaqaHWuMHA3KXuq1wPP38YZbRqqLYI4K3ccAq5EB8MFkoM2lMyncMVS/Tp14YRxFC4ys+Cz6+PeE/Vv4CdloBIdKM5DLEKnHUPnid1AZuJ3YlQM90G1i66gc3Jw9KLE9L0tu7RHseIN6+v0mBbgqLHRzmZzX+Co+VLcSKZyDg=="
Dec 08 09:49:36 volumio volumio[17641]: info: Loading plugin "appearance"...
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-06:00" level=debug msg="completed challenge"
Dec 08 09:49:36 volumio go-librespot[17663]: time="2025-12-08T09:49:36-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 08 09:49:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:37 volumio volumio[17641]: info: Loading plugin "network"...
Dec 08 09:49:37 volumio volumio[17641]: info: Refreshing Cached IP Addresses
Dec 08 09:49:37 volumio sudo[17677]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 08 09:49:37 volumio sudo[17677]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:37 volumio sudo[17679]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 08 09:49:37 volumio sudo[17679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:37 volumio sudo[17677]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:37 volumio volumio[17641]: info: Loading plugin "services"...
Dec 08 09:49:37 volumio sudo[17679]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:37 volumio volumio[17641]: info: Loading plugin "alsa_controller"...
Dec 08 09:49:37 volumio sudo[17688]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 08 09:49:37 volumio sudo[17688]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:37 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 08 09:49:37 volumio volumio[17641]: info: Loading plugin "wizard"...
Dec 08 09:49:37 volumio volumio[17641]: info: Loading plugin "networkfs"...
Dec 08 09:49:37 volumio volumio[17641]: info: Starting Udev Watcher for removable devices
Dec 08 09:49:38 volumio volumio[17641]: info: Ignoring mount for partition: boot
Dec 08 09:49:38 volumio volumio[17641]: info: Ignoring mount for partition: volumio
Dec 08 09:49:38 volumio volumio[17641]: info: Ignoring mount for partition: volumio_data
Dec 08 09:49:38 volumio volumio[17641]: info: Mounting Device Wikipedia
Dec 08 09:49:38 volumio sudo[17716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 08 09:49:38 volumio sudo[17716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:38 volumio sudo[17716]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:38 volumio volumio[17641]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 08 09:49:38 volumio volumio[17641]: dmesg(1) may have more information after failed mount system call.
Dec 08 09:49:38 volumio volumio[17641]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 08 09:49:38 volumio volumio[17641]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 08 09:49:38 volumio volumio[17641]: dmesg(1) may have more information after failed mount system call.
Dec 08 09:49:38 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 08 09:49:38 volumio volumio[17641]: info: Loading plugin "volumio_command_line_client"...
Dec 08 09:49:38 volumio volumio[17641]: info: Loading plugin "upnp"...
Dec 08 09:49:38 volumio volumio[17641]: info: [1765208978099] Starting Upmpd Daemon
Dec 08 09:49:38 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 08 09:49:38 volumio volumio[17641]: info: Loading plugin "my_music"...
Dec 08 09:49:38 volumio volumio[17641]: info: Loading plugin "mpd"...
Dec 08 09:49:38 volumio sudo[17688]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:38 volumio volumio[17641]: info: Loading plugin "upnp_browser"...
Dec 08 09:49:38 volumio volumio-remote-updater[9752]: [2025-12-08 09:49:38] [connect] Successful connection
Dec 08 09:49:39 volumio volumio[17641]: info: Loading plugin "alarm-clock"...
Dec 08 09:49:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31.
Dec 08 09:49:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:39 volumio go-librespot[17718]: go-librespot daemon starting...
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=debug msg="app state loaded"
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:40 volumio volumio[17641]: info: Loading plugin "airplay_emulation"...
Dec 08 09:49:40 volumio volumio[17641]: info: Starting Shairport Sync
Dec 08 09:49:40 volumio volumio[17641]: info: Loading plugin "last_100"...
Dec 08 09:49:40 volumio volumio[17641]: info: Loading plugin "webradio"...
Dec 08 09:49:40 volumio volumio[17641]: info: Loading plugin "i2s_dacs"...
Dec 08 09:49:40 volumio volumio[17641]: info: I2S DAC not set, start Auto-detection
Dec 08 09:49:40 volumio volumio[17641]: info: Loading plugin "volumiodiscovery"...
Dec 08 09:49:40 volumio volumio[17641]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:49:40 volumio volumio[17641]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:49:40 volumio volumio[17641]: *** WARNING *** For more information see
Dec 08 09:49:40 volumio volumio[17641]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:49:40 volumio volumio[17641]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:49:40 volumio volumio[17641]: *** WARNING *** For more information see
Dec 08 09:49:40 volumio node[17641]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:49:40 volumio node[17641]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:49:40 volumio node[17641]: *** WARNING *** For more information see
Dec 08 09:49:40 volumio node[17641]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:49:40 volumio node[17641]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:49:40 volumio node[17641]: *** WARNING *** For more information see
Dec 08 09:49:40 volumio volumio[17641]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-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 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-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 08 09:49:40 volumio volumio[17641]: info: Discovery: Started advertising with name: Volumio
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=info msg="zeroconf server listening on port 37835"
Dec 08 09:49:40 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 08 09:49:40 volumio volumio[17641]: info: Loading plugin "bandcamp"...
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=debug msg="obtained new client token: AACIu8MHu49vFOR6y/ThO6JcBZR7bXaqHMnhiH/OAcB1Bd5R5MhOhFuWMP6w5g51875cWibgoOQ9MSu5vq1KhgIryOy49gw5YGnBe8kX9GdKK+jGmitdYKTOjMkWs3pjML8zlKV84VLebj0oDNXWfynvj11zbrDIaGWwwDs0YupXoh9DExX3t1tmYWKyVGcqrwX/wMUs7yB1ID+M9BOGaA08QuxLPX2/rpMOQ7athnz6/gNXkkAUQXiqYQ=="
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-06:00" level=debug msg="completed challenge"
Dec 08 09:49:40 volumio go-librespot[17719]: time="2025-12-08T09:49:40-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 08 09:49:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:41 volumio volumio[17641]: info: Plugin calmradio is not enabled
Dec 08 09:49:41 volumio volumio[17641]: info: Loading plugin "soundcloud"...
Dec 08 09:49:41 volumio volumio[17641]: info: Loading plugin "spop"...
Dec 08 09:49:42 volumio volumio[17641]: info: Loading plugin "squeezelite_mc"...
Dec 08 09:49:43 volumio volumio[17641]: info: Loading plugin "youtube2"...
Dec 08 09:49:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32.
Dec 08 09:49:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:43 volumio go-librespot[17729]: go-librespot daemon starting...
Dec 08 09:49:43 volumio go-librespot[17730]: time="2025-12-08T09:49:43-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:43 volumio go-librespot[17730]: time="2025-12-08T09:49:43-06:00" level=debug msg="app state loaded"
Dec 08 09:49:43 volumio go-librespot[17730]: time="2025-12-08T09:49:43-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:43 volumio go-librespot[17730]: time="2025-12-08T09:49:43-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49: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 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49: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 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49: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 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49:44-06:00" level=info msg="zeroconf server listening on port 43195"
Dec 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49:44-06:00" level=debug msg="obtained new client token: AADQE+Dh9WEMjD08QgjaMPD+hPLu+Ll7pg0OhXWDZcrDEq7RtstWz5HnhkokV4HrwmvD89BxKbNMIUInPyXBxqMNhCK+Y1d8m68Tc1ct1lwYQYmCzeImkh4I38qPY3+3oGxX2A9WKbY2TEeTPbtsSKvU4FFo1Aof900YcyuTMSlk1FZNUnMLnSy+GSoGz0/JWY6X7X3mVE1XByizw9AowcMTmBezvbIxpU8WsTJE+/j7Ar1aqiCiLls="
Dec 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49:44-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:44 volumio volumio[17641]: info: Loading plugin "ytcr"...
Dec 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49:44-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49:44-06:00" level=debug msg="completed challenge"
Dec 08 09:49:44 volumio go-librespot[17730]: time="2025-12-08T09:49:44-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 08 09:49:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:45 volumio volumio[17641]: info: Loading plugin "ytmusic"...
Dec 08 09:49:46 volumio volumio[17641]: info: Plugin now_playing is not enabled
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "outputs"...
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "albumart"...
Dec 08 09:49:46 volumio volumio[17641]: info: Plugin example_plugin is not enabled
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "inputs"...
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "updater_comm"...
Dec 08 09:49:46 volumio volumio[17641]: info: Plugin mpdemulation is not enabled
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "rest_api"...
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "websocket"...
Dec 08 09:49:46 volumio volumio[17641]: info: Starting Socket.io Server version 1.7.4
Dec 08 09:49:46 volumio volumio[17641]: info: Plugin fusiondsp is not enabled
Dec 08 09:49:46 volumio volumio[17641]: info: Plugin mpdoutput is not enabled
Dec 08 09:49:46 volumio volumio[17641]: info: Plugin RoonBridge is not enabled
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "podcast"...
Dec 08 09:49:46 volumio volumio[17641]: info: ControllerPodcast::constructor
Dec 08 09:49:46 volumio volumio[17641]: info: Loading plugin "volusonic"...
Dec 08 09:49:46 volumio volumio[17737]: Forking 3 albumart workers
Dec 08 09:49:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33.
Dec 08 09:49:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:47 volumio go-librespot[17780]: go-librespot daemon starting...
Dec 08 09:49:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-06:00" level=debug msg="app state loaded"
Dec 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-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 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-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 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-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 08 09:49:47 volumio go-librespot[17781]: time="2025-12-08T09:49:47-06:00" level=info msg="zeroconf server listening on port 43747"
Dec 08 09:49:48 volumio go-librespot[17781]: time="2025-12-08T09:49:48-06:00" level=debug msg="obtained new client token: AADqKSoebLCOx6InQO3MVUEnfjj3kM/hzSU3HZMdx9Nz1mKa5tkoCucYlo3TF5r+FRJQ/ZJRlvt4/eofzBqlm6P2Pjzijokgkx5LUQ9uBkVAsVQA586CQqQK7SwOt+LxVosEzWaMqpBg6EXFr01reDDGYo7WPElyC9C+KdlNvhvK+HCFhELYMokNuEFeQxNyUEeb8hcDJnIl56SiFznbqfoIfDoT8ISU8tBgFMDaNoaIX4+iiXMvp8U="
Dec 08 09:49:48 volumio volumio[17641]: info: Applying required configuration parameters for plugin volusonic
Dec 08 09:49:48 volumio volumio[17641]: info: Loading plugin "backup_restore"...
Dec 08 09:49:48 volumio volumio[17751]: Starting albumart workers
Dec 08 09:49:48 volumio go-librespot[17781]: time="2025-12-08T09:49:48-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:48 volumio volumio[17752]: Starting albumart workers
Dec 08 09:49:48 volumio go-librespot[17781]: time="2025-12-08T09:49:48-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:48 volumio go-librespot[17781]: time="2025-12-08T09:49:48-06:00" level=debug msg="completed challenge"
Dec 08 09:49:48 volumio volumio[17750]: Starting albumart workers
Dec 08 09:49:48 volumio go-librespot[17781]: time="2025-12-08T09:49: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 08 09:49:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:48 volumio volumio[17641]: info: Applying required configuration parameters for plugin backup_restore
Dec 08 09:49:48 volumio volumio[17641]: info: Plugin rpi_eeprom_config is not enabled
Dec 08 09:49:48 volumio volumio[17641]: info: Plugin rpi_eeprom_updater is not enabled
Dec 08 09:49:48 volumio volumio[17641]: info: Loading plugin "scheduledrestart"...
Dec 08 09:49:48 volumio volumio[17641]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 08 09:49:48 volumio volumio[17641]: info: Plugin Bluetoothremote is not enabled
Dec 08 09:49:48 volumio volumio[17641]: info: Plugin music_services_shield is not enabled
Dec 08 09:49:48 volumio volumio[17641]: info: Loading plugin "Systeminfo"...
Dec 08 09:49:49 volumio volumio[17641]: info: Plugin peppymeterbasic is not enabled
Dec 08 09:49:49 volumio volumio[17641]: info: Loading plugin "peppyspectrum"...
Dec 08 09:49:49 volumio volumio[17641]: info: Loading i18n strings for locale en
Dec 08 09:49:49 volumio volumio[17641]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 08 09:49:49 volumio volumio[17641]: Updating browse sources language
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::initPlayerControls
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:49:49 volumio volumio[17641]: Express server listening on port 3000
Dec 08 09:49:49 volumio volumio[17641]: [Metrics] WebUI: 14s 670.73ms
Dec 08 09:49:49 volumio volumio[17641]: info: CoreStateMachine::resetVolumioState
Dec 08 09:49:49 volumio volumio[17641]: info: CoreStateMachine::getcurrentVolume
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::volumioRetrievevolume
Dec 08 09:49:49 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:49 volumio sudo[17825]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 08 09:49:49 volumio sudo[17825]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:49 volumio sudo[17825]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:49 volumio sudo[17827]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 08 09:49:49 volumio sudo[17827]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:49 volumio sudo[17827]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:50 volumio volumio[17641]: info: Volumio Network Manager: Network status updated: 1
Dec 08 09:49:50 volumio volumio[17641]: info: VolumeController:: Volume=86 Mute =false
Dec 08 09:49:50 volumio volumio[17641]: info: CoreStateMachine::pushState
Dec 08 09:49:50 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioPushState
Dec 08 09:49:50 volumio volumio[17641]: info: CoreStateMachine::updateTrackBlock
Dec 08 09:49:50 volumio volumio[17641]: info: CorePlayQueue::getTrackBlock
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioRetrievevolume
Dec 08 09:49:50 volumio volumio[17641]: info: Reloading queue from file
Dec 08 09:49:50 volumio volumio[17641]: info: CoreStateMachine::setRepeat null single undefined
Dec 08 09:49:50 volumio volumio[17641]: info: CoreStateMachine::pushState
Dec 08 09:49:50 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioPushState
Dec 08 09:49:50 volumio volumio[17641]: info: CoreStateMachine::setRandom null
Dec 08 09:49:50 volumio volumio[17641]: info: CoreStateMachine::pushState
Dec 08 09:49:50 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioPushState
Dec 08 09:49:50 volumio volumio[17641]: info: Setting Device type: Raspberry PI
Dec 08 09:49:50 volumio volumio[17641]: info: VolumeController:: Volume=86 Mute =false
Dec 08 09:49:50 volumio volumio[17641]: info: CoreStateMachine::pushState
Dec 08 09:49:50 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioPushState
Dec 08 09:49:50 volumio sudo[17840]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 08 09:49:50 volumio sudo[17840]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:50 volumio volumio[17641]: info: Completed loading Core Plugins
Dec 08 09:49:50 volumio volumio[17641]: info: Preparing to generate the ALSA configuration file
Dec 08 09:49:50 volumio volumio[17641]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 08 09:49:50 volumio volumio[17641]: info: Reading ALSA contributions from plugins.
Dec 08 09:49:50 volumio volumio[17641]: info: Asound.conf file unchanged, so no further update is needed
Dec 08 09:49:50 volumio sudo[17840]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:50 volumio volumio[17641]: info: Output device has changed, restarting MPD
Dec 08 09:49:50 volumio volumio[17641]: info: Output device has changed, restarting Shairport Sync
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:50 volumio sudo[17844]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 08 09:49:50 volumio sudo[17844]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:50 volumio sudo[17846]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 08 09:49:50 volumio sudo[17846]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:50 volumio sudo[17844]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:50 volumio volumio[17641]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:49:50 volumio volumio[17641]: info: ___________ START PLUGINS ___________
Dec 08 09:49:50 volumio volumio[17641]: info: ControllerMpd::onStart: Initializing MPD
Dec 08 09:49:50 volumio volumio[17641]: info: Creating MPD Configuration file
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:50 volumio volumio[17641]: info: [1765208990398] CoreMusicLibrary::Adding element Media Servers
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:50 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 08 09:49:50 volumio sudo[17854]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 08 09:49:50 volumio sudo[17854]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:50 volumio sudo[17856]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 08 09:49:50 volumio sudo[17856]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:50 volumio sudo[17854]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:50 volumio volumio[17641]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:50 volumio volumio[17641]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:50 volumio volumio[17641]: info: [1765208990514] CoreMusicLibrary::Adding element Last_100
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:50 volumio volumio[17641]: info: [1765208990519] CoreMusicLibrary::Adding element Webradio
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:50 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 08 09:49:50 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 08 09:49:50 volumio systemd[1]: mpd.service: Consumed 4.529s CPU time.
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 08 09:49:50 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 08 09:49:50 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 08 09:49:50 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 08 09:49:50 volumio volumio[17641]: info: Initializing BBC Radios
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:50 volumio volumio[17641]: info: [1765208990591] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:50 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:50 volumio volumio[17641]: info: [1765208990604] CoreMusicLibrary::Adding element SoundCloud
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:50 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 08 09:49:50 volumio volumio[17641]: info: Creating Spotify config file
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:50 volumio sudo[17881]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 08 09:49:50 volumio sudo[17881]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 08 09:49:50 volumio sudo[17881]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:50 volumio volumio[17641]: info: [squeezelite_mc] Starting proxy server...
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:50 volumio volumio[17641]: info: [1765208990976] CoreMusicLibrary::Adding element YouTube2
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source YouTube2
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:50 volumio volumio[17641]: info: [1765208990996] CoreMusicLibrary::Adding element YouTube Music
Dec 08 09:49:50 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source YouTube2
Dec 08 09:49:50 volumio volumio[17641]: Cannot find translation for source YouTube Music
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:51 volumio volumio[17641]: info: [1765208991008] CoreMusicLibrary::Adding element Podcast
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube2
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube Music
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Podcast
Dec 08 09:49:51 volumio volumio-remote-updater[9752]: [2025-12-08 09:49:51] [connect] Successful connection
Dec 08 09:49:51 volumio volumio[17641]: info: Loading i18n strings for locale en
Dec 08 09:49:51 volumio volumio[17641]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 08 09:49:51 volumio volumio[17641]: Updating browse sources language
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube2
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube Music
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Podcast
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube2
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube Music
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Podcast
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:51 volumio volumio[17641]: info: [1765208991057] CoreMusicLibrary::Adding element Volusonic
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube2
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source YouTube Music
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Podcast
Dec 08 09:49:51 volumio volumio[17641]: Cannot find translation for source Volusonic
Dec 08 09:49:51 volumio volumio[17641]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 08 09:49:51 volumio volumio[17641]: info: Volumio Calling Home
Dec 08 09:49:51 volumio volumio[17641]: info: [squeezelite_mc] Proxy server started on port 35169
Dec 08 09:49:51 volumio volumio[17641]: info: Preparing to generate the ALSA configuration file
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::volumioRetrievevolume
Dec 08 09:49:51 volumio volumio[17641]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 08 09:49:51 volumio volumio[17641]: info: Discovery: Found device Volumio
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:51 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:51 volumio volumio[17641]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954
Dec 08 09:49:51 volumio volumio[17641]: info: Discovery: Found device Volumio
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:51 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:51 volumio volumio[17641]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 08 09:49:51 volumio volumio[17641]: info: Reading ALSA contributions from plugins.
Dec 08 09:49:51 volumio volumio[17641]: info: MPD Permissions set
Dec 08 09:49:51 volumio volumio[17641]: info: MPD Permissions set
Dec 08 09:49:51 volumio volumio[17641]: info: Upmpdcli Daemon Started
Dec 08 09:49:51 volumio volumio-remote-updater[9752]: [2025-12-08 09:49:51] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765208991 101
Dec 08 09:49:51 volumio volumio[17641]: 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 08 09:49:51 volumio volumio[17641]: info: Spotify config file written
Dec 08 09:49:51 volumio sudo[17890]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 08 09:49:51 volumio sudo[17890]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:51 volumio volumio[17641]: 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 08 09:49:51 volumio volumio[17641]: info: VolumeController:: Volume=86 Mute =false
Dec 08 09:49:51 volumio volumio[17641]: info: CoreStateMachine::pushState
Dec 08 09:49:51 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::volumioPushState
Dec 08 09:49:51 volumio volumio[17641]: info: [squeezelite_mc] Server discovery started
Dec 08 09:49:51 volumio volumio[17641]: info: [squeezelite_mc] Player finder started
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true
Dec 08 09:49:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:51 volumio go-librespot[17892]: go-librespot daemon starting...
Dec 08 09:49:51 volumio sudo[17890]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-06:00" level=debug msg="app state loaded"
Dec 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:51 volumio volumio[17641]: info: No need to fix Spotify hosts
Dec 08 09:49:51 volumio volumio[17641]: 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 08 09:49:51 volumio volumio[17641]: info: Volumio called home
Dec 08 09:49:51 volumio volumio[17641]: 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 08 09:49:51 volumio volumio[17641]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 08 09:49:51 volumio volumio[17641]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-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 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-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 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-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 08 09:49:51 volumio volumio[17641]: 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 08 09:49:51 volumio go-librespot[17894]: time="2025-12-08T09:49:51-06:00" level=info msg="zeroconf server listening on port 45079"
Dec 08 09:49:51 volumio volumio[17641]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 08 09:49:51 volumio volumio[17641]: SPOTIFY: BQBxTh9r4rlYiwAJ4qbxAqcGIQTViBwfi5oRb40W0LGsRyPKCIHs5Q_rgwP4UdCqW2mQ5JF3SAcc1th_IiRH6XnywGa3ZWUeWkuUCru7cMF6F9S3rHXsrJ6FcUvNXc4ukOyfNsrj9O3NcQC_0Ykkw6fF3BWOxoexmbMvJcNxGlpV_UQK_dYpcHiJDBamWLM1zGdxviL5nA5Gg3Pubzf74Zj1VCZi7zv29WX8Mz0
Dec 08 09:49:51 volumio volumio[17641]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 08 09:49:51 volumio volumio[17641]: info: New Spotify access token = BQBxTh9r4rlYiwAJ4qbxAqcGIQTViBwfi5oRb40W0LGsRyPKCIHs5Q_rgwP4UdCqW2mQ5JF3SAcc1th_IiRH6XnywGa3ZWUeWkuUCru7cMF6F9S3rHXsrJ6FcUvNXc4ukOyfNsrj9O3NcQC_0Ykkw6fF3BWOxoexmbMvJcNxGlpV_UQK_dYpcHiJDBamWLM1zGdxviL5nA5Gg3Pubzf74Zj1VCZi7zv29WX8Mz0
Dec 08 09:49:51 volumio volumio[17641]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 08 09:49:51 volumio volumio[17641]: info: Starting Shairport Sync
Dec 08 09:49:51 volumio volumio[17641]: info: Starting Shairport Sync
Dec 08 09:49:52 volumio volumio[17641]: info: Starting Shairport Sync
Dec 08 09:49:52 volumio sudo[17917]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:49:52 volumio sudo[17917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio go-librespot[17894]: time="2025-12-08T09:49:52-06:00" level=debug msg="obtained new client token: AAB2H9c0z8NCw2xQMsA0kANL8PlRV2VWAMzAqp8ZD43ed41yN6h/aniJe8uUCo7npOo2eseO8giLS7M2nYU8BU3kGRxtNL9bYPhntjl8ebkXCb+fgr25g/xi2+5kebxPPL6egkfCsAEWxU7WdcEw6rQSGwaStEmZav4IC2VXtXA8zNdb4YjaMocBP2+GILONYn9hgdey7m5ytTAeCO5kNP0MTBR/AUqzyMDmEoZk0dwreuucqfQf+Yo="
Dec 08 09:49:52 volumio sudo[17920]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:49:52 volumio sudo[17920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio sudo[17922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:49:52 volumio sudo[17922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 08 09:49:52 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 08 09:49:52 volumio go-librespot[17894]: time="2025-12-08T09:49:52-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:52 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:52 volumio systemd[1]: shairport-sync.service: Consumed 2.052s CPU time.
Dec 08 09:49:52 volumio volumio[17641]: info: Asound.conf file unchanged, so no further update is needed
Dec 08 09:49:52 volumio volumio[17641]: info: Output device has changed, restarting MPD
Dec 08 09:49:52 volumio sudo[17915]: 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 08 09:49:52 volumio sudo[17915]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio volumio[17641]: info: Output device has changed, restarting Shairport Sync
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:52 volumio go-librespot[17894]: time="2025-12-08T09:49:52-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:52 volumio sudo[17915]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio go-librespot[17894]: time="2025-12-08T09:49:52-06:00" level=debug msg="completed challenge"
Dec 08 09:49:52 volumio sudo[17930]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 08 09:49:52 volumio sudo[17930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio sudo[17927]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 08 09:49:52 volumio sudo[17927]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio volumio[17641]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:49:52 volumio sudo[17927]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio go-librespot[17894]: time="2025-12-08T09:49: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 08 09:49:52 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:52 volumio sudo[17917]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:52 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 08 09:49:52 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 08 09:49:52 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 08 09:49:52 volumio systemd[1]: mpd.service: Consumed 1.605s CPU time.
Dec 08 09:49:52 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 08 09:49:52 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:52 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 08 09:49:52 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 08 09:49:52 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 08 09:49:52 volumio volumio[17641]: info: MPD Permissions set
Dec 08 09:49:52 volumio volumio[17641]: info: Shairport-Sync Started
Dec 08 09:49:52 volumio volumio[17641]: Error adding Membership: Error: addMembership EINVAL
Dec 08 09:49:52 volumio volumio[17641]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 08 09:49:52 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 08 09:49:52 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 08 09:49:52 volumio sudo[17956]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 08 09:49:52 volumio sudo[17956]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:52 volumio sudo[17920]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio sudo[17922]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio sudo[17956]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio volumio[17641]: info: Shairport-Sync Started
Dec 08 09:49:52 volumio volumio[17641]: info: Shairport-Sync Started
Dec 08 09:49:52 volumio volumio[17641]: 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 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:52 volumio volumio[17641]: 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 08 09:49:52 volumio volumio[17641]: info: Spotify Successfully logged in
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:49:52 volumio volumio[17641]: info: [1765208992707] CoreMusicLibrary::Adding element Spotify
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:49:52 volumio volumio[17641]: Cannot find translation for source Bandcamp Discover
Dec 08 09:49:52 volumio volumio[17641]: Cannot find translation for source SoundCloud
Dec 08 09:49:52 volumio volumio[17641]: Cannot find translation for source YouTube2
Dec 08 09:49:52 volumio volumio[17641]: Cannot find translation for source YouTube Music
Dec 08 09:49:52 volumio volumio[17641]: Cannot find translation for source Podcast
Dec 08 09:49:52 volumio volumio[17641]: Cannot find translation for source Volusonic
Dec 08 09:49:52 volumio volumio[17641]: Cannot find translation for source Spotify
Dec 08 09:49:52 volumio sudo[17957]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 08 09:49:52 volumio sudo[17957]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 08 09:49:52 volumio volumio[17641]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:52 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:52 volumio sudo[17957]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio volumio[17641]: info: Starting Shairport Sync
Dec 08 09:49:52 volumio sudo[17977]: 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 08 09:49:52 volumio sudo[17977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio sudo[17977]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:52 volumio sudo[17987]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:49:52 volumio sudo[17987]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 08 09:49:52 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true
Dec 08 09:49:52 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 08 09:49:52 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:52 volumio sudo[17990]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 08 09:49:52 volumio sudo[17990]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:52 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:49:53 volumio sudo[17987]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:53 volumio systemd[1]: Reloading.
Dec 08 09:49:53 volumio volumio[17641]: info: Shairport-Sync Started
Dec 08 09:49:53 volumio volumio[17641]: info: [squeezelite_mc] Notification listener started
Dec 08 09:49:53 volumio volumio[17641]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 08 09:49:53 volumio volumio[17641]: 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 08 09:49:53 volumio volumio[17641]: 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 08 09:49:53 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:53 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:53 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:49:53 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:49:54 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 08 09:49:54 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 08 09:49:55 volumio volumio[17641]: info: go-librespot daemon successfully initialized
Dec 08 09:49:55 volumio volumio[17641]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:55 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:55 volumio sudo[17990]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:55 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:55 volumio sudo[18026]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:55 volumio sudo[18026]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:55 volumio sudo[18026]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:55 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 08 09:49:55 volumio sudo[18029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 08 09:49:55 volumio sudo[18029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:55 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 08 09:49:55 volumio volumio[17641]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 08 09:49:55 volumio volumio[17641]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:55 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34.
Dec 08 09:49:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:55 volumio go-librespot[18031]: go-librespot daemon starting...
Dec 08 09:49:55 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 08 09:49:55 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49:55-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49:55-06:00" level=debug msg="app state loaded"
Dec 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49:55-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:55 volumio sudo[18029]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49:55-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49: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 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49: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 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49: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 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49:55-06:00" level=info msg="zeroconf server listening on port 42913"
Dec 08 09:49:55 volumio go-librespot[18032]: time="2025-12-08T09:49:55-06:00" level=debug msg="obtained new client token: AAC9LdudJolhAIc2IDfhQU0OZwiXfOGURep3EvjeKKqhb2ix4AAsd3Z0jui5WnoTe6dh68MrnebDLJgDMUK67TECpREgoAugJLZo1Bv8ErYKI+Kho06lKa6DTcf9/xMojkcPktXW/mQNo+xLfmRUlQFUPnDzbVxd9jLyKZRXgEoIn9BLV4Q6xdX7qrut2fFmCS3NiT9wu5YydcSGNpupqlDKwyWblpzMp5l5uspC+1/PH59NyzMafohNLg=="
Dec 08 09:49:56 volumio go-librespot[18032]: time="2025-12-08T09:49:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:56 volumio go-librespot[18032]: time="2025-12-08T09:49:56-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:56 volumio go-librespot[18032]: time="2025-12-08T09:49:56-06:00" level=debug msg="completed challenge"
Dec 08 09:49:56 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:56 volumio go-librespot[18032]: time="2025-12-08T09:49: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 08 09:49:56 volumio sudo[18040]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:56 volumio sudo[18040]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:56 volumio sudo[18040]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:56 volumio volumio[17641]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 08 09:49:56 volumio sudo[18044]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 08 09:49:56 volumio sudo[18044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:56 volumio sudo[18044]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:56 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 08 09:49:56 volumio sudo[18047]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 08 09:49:56 volumio sudo[18047]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:56 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 08 09:49:56 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 08 09:49:56 volumio sudo[18047]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:56 volumio volumio[17641]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 08 09:49:56 volumio volumio[17641]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 08 09:49:56 volumio volumio[17641]: 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 08 09:49:56 volumio volumio[17641]: 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 08 09:49:56 volumio mpd[17984]: 2025-12-08T09:49:56 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 08 09:49:56 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 08 09:49:56 volumio sudo[17856]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:56 volumio sudo[17930]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:56 volumio sudo[17846]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:56 volumio volumio[17641]: error: MPD error: The expression evaluated to a falsy value:
Dec 08 09:49:56 volumio volumio[17641]: assert.ok(self.idling)
Dec 08 09:49:56 volumio volumio[17641]: error: The expression evaluated to a falsy value:
Dec 08 09:49:56 volumio volumio[17641]: assert.ok(self.idling)
Dec 08 09:49:56 volumio volumio[17641]: error: MPD error: The expression evaluated to a falsy value:
Dec 08 09:49:56 volumio volumio[17641]: assert.ok(self.idling)
Dec 08 09:49:56 volumio volumio[17641]: error: The expression evaluated to a falsy value:
Dec 08 09:49:56 volumio volumio[17641]: assert.ok(self.idling)
Dec 08 09:49:56 volumio volumio[17641]: info: MPD running with PID17984
Dec 08 09:49:56 volumio volumio[17641]: ,establishing connection
Dec 08 09:49:56 volumio volumio[17641]: error: updateQueue error: null
Dec 08 09:49:56 volumio volumio[17641]: error: updateQueue error: null
Dec 08 09:49:56 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:57 volumio sudo[18058]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:57 volumio sudo[18058]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:57 volumio sudo[18058]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:57 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:57 volumio sudo[18061]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:57 volumio sudo[18061]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:57 volumio volumio[17641]: info: CoreCommandRouter::volumioGetState
Dec 08 09:49:57 volumio volumio[17641]: info: CorePlayQueue::getTrack 0
Dec 08 09:49:57 volumio sudo[18061]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:58 volumio volumio[17641]: info: Initializing connection to go-librespot Websocket
Dec 08 09:49:58 volumio volumio[17641]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:49:58 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:58 volumio sudo[18078]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:58 volumio sudo[18078]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:58 volumio sudo[18078]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:58 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:58 volumio sudo[18081]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:58 volumio sudo[18081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:58 volumio sudo[18081]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35.
Dec 08 09:49:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:49:59 volumio go-librespot[18083]: go-librespot daemon starting...
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=debug msg="app state loaded"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=debug msg="stored credentials not found"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:49:59 volumio volumio[17641]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:49:59 volumio sudo[18091]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:49:59 volumio sudo[18091]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:59 volumio sudo[18091]: pam_unix(sudo:session): session closed for user root
Dec 08 09:49:59 volumio volumio[17641]: info: Completed starting Core Plugins
Dec 08 09:49:59 volumio volumio[17641]: info: -------------------------------------------
Dec 08 09:49:59 volumio volumio[17641]: info: ----- MyVolumio plugins startup ----
Dec 08 09:49:59 volumio volumio[17641]: info: -------------------------------------------
Dec 08 09:49:59 volumio volumio[17641]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-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 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-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 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=info msg="zeroconf server listening on port 42891"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=debug msg="obtained new client token: AAAH3hKiF5OePlAy1gZVpEoYmnhn9cd+Z2USWilnWwJaLchodb3npAP+6A1RwLn/uh18CybMznSm4lkTVKiLkQeC0zMbpTSii5wo/iMFR1zNoXTuhNqRN5C0rC4FRkr7bnn/WhpyqPLqcx76LmfPC/JnOKvzhl8stp5tv4Wpz8f4lbLKDcxY2bGTT7V/2NB69Wc6Zge3bkXBb6Tsmz8gQlNQlKu/s9rF8nIBI5UKCXyXdShK4aKrtfaY4g=="
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=debug msg="completed keyexchange"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-06:00" level=debug msg="completed challenge"
Dec 08 09:49:59 volumio go-librespot[18084]: time="2025-12-08T09:49:59-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 08 09:49:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:49:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:49:59 volumio sudo[18095]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:49:59 volumio sudo[18095]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:59 volumio sudo[18097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:49:59 volumio sudo[18097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:59 volumio sudo[18100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:49:59 volumio sudo[18100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:49:59 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 08 09:49:59 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 08 09:49:59 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 08 09:50:00 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 08 09:50:00 volumio sudo[18095]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:00 volumio mpd_monitor.sh[18103]: MPD Monitor Service: Starting MPD Monitor Service
Dec 08 09:50:00 volumio sudo[18100]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:00 volumio sudo[18097]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:00 volumio volumio[17641]: info: Successfully started MPD Monitor
Dec 08 09:50:00 volumio volumio[17641]: info: Successfully started MPD Monitor
Dec 08 09:50:00 volumio volumio[17641]: info: Successfully started MPD Monitor
Dec 08 09:50:01 volumio volumio[17641]: info: Initializing connection to go-librespot Websocket
Dec 08 09:50:01 volumio volumio[17641]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:50:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36.
Dec 08 09:50:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:02 volumio go-librespot[18107]: go-librespot daemon starting...
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=debug msg="app state loaded"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50: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 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50: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 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=info msg="zeroconf server listening on port 35979"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=debug msg="obtained new client token: AABwZ/tP0HcS6ja7nbU6e9cG63AzM3rEf/kVlyZWQTUnLPWZ99i/n7Mf5vTQ0bQIeY8FqBsSflO9TZtRjcIgZjfbAigzriUru6oeNLQHA/Szx8ilOokwXhTcS0b6Jfyc2t50N4bmZsh0W0BNWdvFh6DzOLzNYWvcsQx9hcl6eny6qMJRSmJiaCehhM7n8KgOLATiU+NpmflF23vvDOKN4DQR6uM4a4NkKn62n7StGZxgr/RW85mgBe1whg=="
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50:03-06:00" level=debug msg="completed challenge"
Dec 08 09:50:03 volumio go-librespot[18108]: time="2025-12-08T09:50: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 08 09:50:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:04 volumio volumio[17641]: info: Initializing connection to go-librespot Websocket
Dec 08 09:50:04 volumio volumio[17641]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:50:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37.
Dec 08 09:50:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:06 volumio go-librespot[18116]: go-librespot daemon starting...
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="app state loaded"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=info msg="zeroconf server listening on port 42415"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="obtained new client token: AADj/5XCoeoE/QbO+59lq1Xbt6Sr239QpsQsewAzO6fPkmgKT4CTS+5KSqNPA8kkeJDKPWmVflzhn555ghrztwoOhoyZ5EO8jgT/+yKkK+YyZFzTPkpwCZRcJKy//PoYM1oC5IPeGvqNQWI/BB8L6ul2ud89SiGwYFApma/5dnHaKQWyaJu5Yxneu1LkRthtg/yZi8Ldnt7K7JL42FvF1fg4Npy56S9xn02Ip7FKukmCwns7x7CO4gsBHw=="
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=debug msg="completed challenge"
Dec 08 09:50:07 volumio go-librespot[18117]: time="2025-12-08T09:50:07-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:07 volumio volumio[17641]: info: Initializing connection to go-librespot Websocket
Dec 08 09:50:07 volumio volumio[17641]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 08 09:50:07 volumio volumio[17641]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 08 09:50:07 volumio volumio[17641]: info: Adding plugin multiroom to MyMusic Plugins
Dec 08 09:50:07 volumio volumio[17641]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 08 09:50:07 volumio volumio[17641]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 08 09:50:07 volumio volumio[17641]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 08 09:50:07 volumio volumio[17641]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 08 09:50:07 volumio volumio[17641]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 08 09:50:07 volumio volumio[17641]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 08 09:50:08 volumio volumio[17641]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 08 09:50:08 volumio volumio[17641]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 08 09:50:08 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:08 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:08 volumio volumio[17641]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 08 09:50:08 volumio volumio[17641]: info: MyVolumio login type: Token
Dec 08 09:50:08 volumio volumio[17641]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 08 09:50:08 volumio volumio[17641]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 08 09:50:09 volumio volumio[17641]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 08 09:50:09 volumio volumio[17641]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 08 09:50:09 volumio volumio[17641]: info: Streaming services startup
Dec 08 09:50:09 volumio volumio[17641]: info: Starting Streaming Daemon
Dec 08 09:50:09 volumio sudo[18140]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 08 09:50:09 volumio sudo[18140]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:09 volumio volumio[17641]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 08 09:50:09 volumio sudo[18140]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:09 volumio volumio[17641]: error: Cannot start Volumio Streaming Daemon
Dec 08 09:50:09 volumio volumio[17641]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 08 09:50:09 volumio volumio[17641]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 08 09:50:09 volumio volumio[17641]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 08 09:50:10 volumio volumio[17641]: info: MyVolumio token set successfully
Dec 08 09:50:10 volumio volumio[17641]: info: MYVOLUMIO: Adding device
Dec 08 09:50:10 volumio volumio[17641]: info: MYVOLUMIO: Evaluating Server
Dec 08 09:50:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38.
Dec 08 09:50:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:10 volumio volumio[17641]: info: Initializing connection to go-librespot Websocket
Dec 08 09:50:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:10 volumio go-librespot[18164]: go-librespot daemon starting...
Dec 08 09:50:10 volumio volumio[17641]: info: MyVolumio status changed
Dec 08 09:50:10 volumio volumio[17641]: info: Streaming services startup
Dec 08 09:50:10 volumio volumio[17641]: info: Starting Streaming Daemon
Dec 08 09:50:10 volumio volumio[17641]: info: Removing browser output: myVolumio user plan is not superstar
Dec 08 09:50:10 volumio volumio[17641]: info: Removing audio output:
Dec 08 09:50:10 volumio volumio[17641]: info: Stoppping Tunnel 1
Dec 08 09:50:10 volumio go-librespot[18168]: time="2025-12-08T09:50:10-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:10 volumio go-librespot[18168]: time="2025-12-08T09:50:10-06:00" level=debug msg="app state loaded"
Dec 08 09:50:10 volumio go-librespot[18168]: time="2025-12-08T09:50:10-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:10 volumio go-librespot[18168]: time="2025-12-08T09:50:10-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:10 volumio sudo[18175]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 08 09:50:10 volumio sudo[18175]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:10 volumio sudo[18177]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 08 09:50:10 volumio sudo[18177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:10 volumio go-librespot[18168]: time="2025-12-08T09:50:10-06:00" level=debug msg="new websocket client"
Dec 08 09:50:10 volumio volumio[17641]: info: Connection to go-librespot Websocket established
Dec 08 09:50:10 volumio sudo[18175]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:10 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 08 09:50:10 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 08 09:50:10 volumio volumio[17641]: error: Cannot start Volumio Streaming Daemon
Dec 08 09:50:10 volumio volumio[17641]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 08 09:50:10 volumio volumio[17641]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 08 09:50:10 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 08 09:50:10 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 08 09:50:10 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 08 09:50:10 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 08 09:50:10 volumio sudo[18177]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:10 volumio volumio[17641]: info: Remote SSH Stopped
Dec 08 09:50:10 volumio volumio[17641]: info: Setting Geolocation for MyVolumio to us4
Dec 08 09:50:10 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:10 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:10 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=info msg="zeroconf server listening on port 41015"
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=debug msg="obtained new client token: AAAb6o8KBR9vDFSe8M/mbipAlxWR1rZoB4m027ZE33qJBLHBfGGi8tqWlq085PANE7O7OWXCCk/dbSkNii3g0XrQs8VZYqNXqzyfjxqRmx2mLDZCKnRLDrqv57kvRu0bY9AdqeZ/Iwyy6DmkJ4Wbx31UGFoab9K7Cwsan7zYgIedhHRMXdpzVXi7+dHepAUepKQTEg33rFqvsMdVJsHKJK3Vr594mark+3TVU718+6WLEBpDjdTPtN8="
Dec 08 09:50:11 volumio volumio[17641]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=debug msg="completed challenge"
Dec 08 09:50:11 volumio go-librespot[18168]: time="2025-12-08T09:50:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:11 volumio volumio[17641]: info: Connection to go-librespot Websocket closed
Dec 08 09:50:11 volumio volumio[17641]: info: Updating MyVolumio device info
Dec 08 09:50:11 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:11 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:11 volumio volumio[17641]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:12 volumio volumio[17641]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 08 09:50:13 volumio volumio[17641]: info: Getting Spotify volume
Dec 08 09:50:13 volumio volumio[17641]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 08 09:50:13 volumio volumio[17641]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:50:13 volumio volumio[17641]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 08 09:50:13 volumio volumio[17641]: errno: -111,
Dec 08 09:50:13 volumio volumio[17641]: code: 'ECONNREFUSED',
Dec 08 09:50:13 volumio volumio[17641]: syscall: 'connect',
Dec 08 09:50:13 volumio volumio[17641]: address: '127.0.0.1',
Dec 08 09:50:13 volumio volumio[17641]: port: 9879,
Dec 08 09:50:13 volumio volumio[17641]: response: undefined
Dec 08 09:50:13 volumio volumio[17641]: }
Dec 08 09:50:13 volumio volumio[17641]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 08 09:50:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39.
Dec 08 09:50:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:14 volumio go-librespot[18193]: go-librespot daemon starting...
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-06:00" level=debug msg="app state loaded"
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:14 volumio sudo[18202]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 09:49'
Dec 08 09:50:14 volumio sudo[18202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50: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-gew1.spotify.com:80]"
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-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 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-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 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-06:00" level=info msg="zeroconf server listening on port 35339"
Dec 08 09:50:14 volumio sudo[18202]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-06:00" level=debug msg="obtained new client token: AAD/BqD3Lmq2E7+yvWEwXORkt1wXoS6afQZQiOKPXlFf3yHolYAeNWwGH4BAJLIlM5FHwRY7aDbrtW5IxDIYm+MPa4pSaA5/Qb/E6xC55Np7KcupTL/e8rgNg7wx7hUYubkD1I29vAjqH4bv/GASBSP0pRh0QaccwFY2TnR3ELcyThy2drEa6uBdYv4OyFnKHC8clGg1V9tuPZL1VEvCJC6L+kTx57DPG/zrbUQE6OjBA/N9/i0Vsdkk2Q=="
Dec 08 09:50:14 volumio volumio-remote-updater[9752]: [2025-12-08 09:50:14] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 08 09:50:14 volumio volumio-remote-updater[9752]: [2025-12-08 09:50:14] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 08 09:50:14 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:14 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 08 09:50:14 volumio systemd[1]: volumio.service: Consumed 45.777s CPU time.
Dec 08 09:50:14 volumio go-librespot[18194]: time="2025-12-08T09:50:14-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:15 volumio go-librespot[18194]: time="2025-12-08T09:50:15-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:15 volumio go-librespot[18194]: time="2025-12-08T09:50:15-06:00" level=debug msg="completed challenge"
Dec 08 09:50:15 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 08 09:50:15 volumio go-librespot[18194]: time="2025-12-08T09:50:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:15 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 08 09:50:15 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 23146.
Dec 08 09:50:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:15 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 08 09:50:15 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 08 09:50:15 volumio systemd[1]: volumio.service: Consumed 45.777s CPU time.
Dec 08 09:50:15 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 08 09:50:15 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 08 09:50:17 volumio volumio[18215]: info: -------------------------------------------
Dec 08 09:50:17 volumio volumio[18215]: info: ----- Volumio3 ----
Dec 08 09:50:17 volumio volumio[18215]: info: -------------------------------------------
Dec 08 09:50:17 volumio volumio[18215]: info: ----- System startup ----
Dec 08 09:50:17 volumio volumio[18215]: info: -------------------------------------------
Dec 08 09:50:17 volumio volumio[18215]: info: MYVOLUMIO Environment detected
Dec 08 09:50:17 volumio volumio[18215]: info: Plugin folders cleanup
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning into folder /volumio/app/plugins/
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category audio_interface
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category miscellanea
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category music_service
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category plugins.json
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category system_controller
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category user_interface
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning into folder /data/plugins/
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category audio_interface
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category music_service
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category system_controller
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category system_hardware
Dec 08 09:50:17 volumio volumio[18215]: info: Scanning category user_interface
Dec 08 09:50:17 volumio volumio[18215]: info: Plugin folders cleanup completed
Dec 08 09:50:17 volumio volumio[18215]: info: -------------------------------------------
Dec 08 09:50:17 volumio volumio[18215]: info: ----- Core plugins startup ----
Dec 08 09:50:17 volumio volumio[18215]: info: -------------------------------------------
Dec 08 09:50:17 volumio volumio[18215]: info: Loading plugins from folder /volumio/app/plugins/
Dec 08 09:50:17 volumio volumio[18215]: info: Adding plugin upnp to MyMusic Plugins
Dec 08 09:50:17 volumio volumio[18215]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 08 09:50:17 volumio volumio[18215]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 08 09:50:17 volumio volumio[18215]: info: Loading plugins from folder /data/plugins/
Dec 08 09:50:17 volumio volumio[18215]: info: Loading plugin "system"...
Dec 08 09:50:17 volumio volumio[18215]: info: Loading plugin "appearance"...
Dec 08 09:50:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40.
Dec 08 09:50:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:18 volumio go-librespot[18242]: go-librespot daemon starting...
Dec 08 09:50:18 volumio go-librespot[18243]: time="2025-12-08T09:50:18-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:18 volumio go-librespot[18243]: time="2025-12-08T09:50:18-06:00" level=debug msg="app state loaded"
Dec 08 09:50:18 volumio go-librespot[18243]: time="2025-12-08T09:50:18-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:18 volumio go-librespot[18243]: time="2025-12-08T09:50:18-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "network"...
Dec 08 09:50:19 volumio volumio[18215]: info: Refreshing Cached IP Addresses
Dec 08 09:50:19 volumio sudo[18251]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 08 09:50:19 volumio sudo[18251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:19 volumio sudo[18253]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 08 09:50:19 volumio sudo[18253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "services"...
Dec 08 09:50:19 volumio sudo[18253]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:19 volumio sudo[18251]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "alsa_controller"...
Dec 08 09:50:19 volumio sudo[18260]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 08 09:50:19 volumio sudo[18260]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:19 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "wizard"...
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "networkfs"...
Dec 08 09:50:19 volumio volumio[18215]: info: Starting Udev Watcher for removable devices
Dec 08 09:50:19 volumio volumio[18215]: info: Ignoring mount for partition: boot
Dec 08 09:50:19 volumio volumio[18215]: info: Ignoring mount for partition: volumio
Dec 08 09:50:19 volumio volumio[18215]: info: Ignoring mount for partition: volumio_data
Dec 08 09:50:19 volumio volumio[18215]: info: Mounting Device Wikipedia
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-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 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-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 08 09:50:19 volumio sudo[18290]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 08 09:50:19 volumio sudo[18290]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-06:00" level=info msg="zeroconf server listening on port 41319"
Dec 08 09:50:19 volumio sudo[18290]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:19 volumio volumio[18215]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 08 09:50:19 volumio volumio[18215]: dmesg(1) may have more information after failed mount system call.
Dec 08 09:50:19 volumio volumio[18215]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 08 09:50:19 volumio volumio[18215]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 08 09:50:19 volumio volumio[18215]: dmesg(1) may have more information after failed mount system call.
Dec 08 09:50:19 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "volumio_command_line_client"...
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "upnp"...
Dec 08 09:50:19 volumio volumio[18215]: info: [1765209019347] Starting Upmpd Daemon
Dec 08 09:50:19 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "my_music"...
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "mpd"...
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-06:00" level=debug msg="obtained new client token: AAD76JSfc0fw/PBLtC4dWYukiBVclBcYRXd3CgslGDGQPWOUQ2apQuVmBCKYW9Oa/ww+AcmhYR9D3jvszc3aZjYZEO8OHwKj64lT0SreKaGgpPF8COwRfr2rBbrQZsKwDetTRhIaA8aBZQKWjJz3/4oT5lRDCAh4d3o7gic2xH85qt7Cn1+Bt420m3dKAd+wZq9WbqDEFI0oJmYupEqamhU6o4ZLU6q/5iDXPbUi7/9n8apgILCD/+RpGQ=="
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-06:00" level=debug msg="completed challenge"
Dec 08 09:50:19 volumio go-librespot[18243]: time="2025-12-08T09:50:19-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 08 09:50:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:19 volumio sudo[18260]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:19 volumio volumio[18215]: info: Loading plugin "upnp_browser"...
Dec 08 09:50:19 volumio volumio-remote-updater[9752]: [2025-12-08 09:50:19] [connect] Successful connection
Dec 08 09:50:21 volumio volumio[18215]: info: Loading plugin "alarm-clock"...
Dec 08 09:50:21 volumio volumio[18215]: info: Loading plugin "airplay_emulation"...
Dec 08 09:50:21 volumio volumio[18215]: info: Starting Shairport Sync
Dec 08 09:50:21 volumio volumio[18215]: info: Loading plugin "last_100"...
Dec 08 09:50:21 volumio volumio[18215]: info: Loading plugin "webradio"...
Dec 08 09:50:21 volumio volumio[18215]: info: Loading plugin "i2s_dacs"...
Dec 08 09:50:21 volumio volumio[18215]: info: I2S DAC not set, start Auto-detection
Dec 08 09:50:21 volumio volumio[18215]: info: Loading plugin "volumiodiscovery"...
Dec 08 09:50:21 volumio volumio[18215]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:50:21 volumio volumio[18215]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:50:21 volumio volumio[18215]: *** WARNING *** For more information see
Dec 08 09:50:21 volumio volumio[18215]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:50:21 volumio volumio[18215]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:50:21 volumio volumio[18215]: *** WARNING *** For more information see
Dec 08 09:50:21 volumio node[18215]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:50:21 volumio node[18215]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:50:21 volumio node[18215]: *** WARNING *** For more information see
Dec 08 09:50:21 volumio node[18215]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 08 09:50:21 volumio node[18215]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 08 09:50:21 volumio node[18215]: *** WARNING *** For more information see
Dec 08 09:50:21 volumio volumio[18215]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 08 09:50:21 volumio volumio[18215]: info: Discovery: Started advertising with name: Volumio
Dec 08 09:50:21 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 08 09:50:21 volumio volumio[18215]: info: Loading plugin "bandcamp"...
Dec 08 09:50:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41.
Dec 08 09:50:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:22 volumio go-librespot[18297]: go-librespot daemon starting...
Dec 08 09:50:22 volumio volumio[18215]: info: Plugin calmradio is not enabled
Dec 08 09:50:22 volumio volumio[18215]: info: Loading plugin "soundcloud"...
Dec 08 09:50:22 volumio go-librespot[18298]: time="2025-12-08T09:50:22-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:22 volumio go-librespot[18298]: time="2025-12-08T09:50:22-06:00" level=debug msg="app state loaded"
Dec 08 09:50:22 volumio go-librespot[18298]: time="2025-12-08T09:50:22-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:22 volumio go-librespot[18298]: time="2025-12-08T09:50:22-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-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 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-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 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-06:00" level=info msg="zeroconf server listening on port 36881"
Dec 08 09:50:23 volumio volumio[18215]: info: Loading plugin "spop"...
Dec 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-06:00" level=debug msg="obtained new client token: AAATfhXy9G0/Zgyw72w4LJVFM5uoxjlJkdMpeNPHZZ2jczYZUIGahQ+8yrsWaCJ4jH7PKaUxMKtzaVkpZBhuXdOg/vsm9gmYSXp6/vxAJyFHtM2FnZOsi+0p3gdYZ1C7W3+qp5ydiPGz7hi9OYiRR/X6CRxQoQAOTP4WU7TwXF3Wfhtmii1i54yoT6QQYASRX6q5+fx53kuGtILPDIXDlWKiSL3Lv6xZO1D2ffhtLCjESuyZdIT7Fy0="
Dec 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-06:00" level=debug msg="completed challenge"
Dec 08 09:50:23 volumio go-librespot[18298]: time="2025-12-08T09:50:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:24 volumio volumio[18215]: info: Loading plugin "squeezelite_mc"...
Dec 08 09:50:24 volumio volumio[18215]: info: Loading plugin "youtube2"...
Dec 08 09:50:25 volumio volumio[18215]: info: Loading plugin "ytcr"...
Dec 08 09:50:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42.
Dec 08 09:50:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:26 volumio go-librespot[18305]: go-librespot daemon starting...
Dec 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-06:00" level=debug msg="app state loaded"
Dec 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-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 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-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 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-06:00" level=info msg="zeroconf server listening on port 36369"
Dec 08 09:50:26 volumio volumio[18215]: info: Loading plugin "ytmusic"...
Dec 08 09:50:26 volumio go-librespot[18306]: time="2025-12-08T09:50:26-06:00" level=debug msg="obtained new client token: AACmGHRXpeixZL6PPX9giGbUYxricr5Pg/YHRYznwiCrOyNlTPx6zFYCb2sRw+pP7FErwUVC9ThDtky4LwAJAwFeC1kABvaqFfE43OxggklO1rgp1OxzNanXCdXSjzKsMt9fTi7BQjeGp1kxIH83cnJrrXzhsDtGG6qUC1o7l+z1qQaVcVs71WBMSE6UcA6JeJmdF8S2jLpPfCIXDo9FnpIenipZ3dVFJhrfJc6n2zuMt6qaoa4iP4v8Vg=="
Dec 08 09:50:27 volumio go-librespot[18306]: time="2025-12-08T09:50:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:27 volumio go-librespot[18306]: time="2025-12-08T09:50:27-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:27 volumio go-librespot[18306]: time="2025-12-08T09:50:27-06:00" level=debug msg="completed challenge"
Dec 08 09:50:27 volumio go-librespot[18306]: time="2025-12-08T09:50:27-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:27 volumio volumio[18215]: info: Plugin now_playing is not enabled
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "outputs"...
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "albumart"...
Dec 08 09:50:27 volumio volumio[18215]: info: Plugin example_plugin is not enabled
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "inputs"...
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "updater_comm"...
Dec 08 09:50:27 volumio volumio[18215]: info: Plugin mpdemulation is not enabled
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "rest_api"...
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "websocket"...
Dec 08 09:50:27 volumio volumio[18215]: info: Starting Socket.io Server version 1.7.4
Dec 08 09:50:27 volumio volumio[18215]: info: Plugin fusiondsp is not enabled
Dec 08 09:50:27 volumio volumio[18215]: info: Plugin mpdoutput is not enabled
Dec 08 09:50:27 volumio volumio[18215]: info: Plugin RoonBridge is not enabled
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "podcast"...
Dec 08 09:50:27 volumio volumio[18215]: info: ControllerPodcast::constructor
Dec 08 09:50:27 volumio volumio[18215]: info: Loading plugin "volusonic"...
Dec 08 09:50:27 volumio volumio[18314]: Forking 3 albumart workers
Dec 08 09:50:29 volumio volumio[18215]: info: Applying required configuration parameters for plugin volusonic
Dec 08 09:50:29 volumio volumio[18215]: info: Loading plugin "backup_restore"...
Dec 08 09:50:29 volumio volumio[18326]: Starting albumart workers
Dec 08 09:50:29 volumio volumio[18325]: Starting albumart workers
Dec 08 09:50:29 volumio volumio[18324]: Starting albumart workers
Dec 08 09:50:29 volumio volumio[18215]: info: Applying required configuration parameters for plugin backup_restore
Dec 08 09:50:29 volumio volumio[18215]: info: Plugin rpi_eeprom_config is not enabled
Dec 08 09:50:29 volumio volumio[18215]: info: Plugin rpi_eeprom_updater is not enabled
Dec 08 09:50:29 volumio volumio[18215]: info: Loading plugin "scheduledrestart"...
Dec 08 09:50:30 volumio volumio[18215]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 08 09:50:30 volumio volumio[18215]: info: Plugin Bluetoothremote is not enabled
Dec 08 09:50:30 volumio volumio[18215]: info: Plugin music_services_shield is not enabled
Dec 08 09:50:30 volumio volumio[18215]: info: Loading plugin "Systeminfo"...
Dec 08 09:50:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 43.
Dec 08 09:50:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:30 volumio go-librespot[18369]: go-librespot daemon starting...
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=debug msg="app state loaded"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:30 volumio volumio[18215]: info: Plugin peppymeterbasic is not enabled
Dec 08 09:50:30 volumio volumio[18215]: info: Loading plugin "peppyspectrum"...
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-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 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-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 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=info msg="zeroconf server listening on port 36759"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=debug msg="obtained new client token: AAAFN1OMv8UxkWm54P7wK5A8O6MtLmDZe0gy/glgEJ5IZ6bCb8dJMwotBUjFk7WN89Kf6bQWqGsKOabxmSQsdtOjdrRdjiex/BWn4U5BBZUoJH6m9TrkfXN4EPjqfHoaNMcj/nj/2VfXBjhhJR3nOductYu0iQAd8tCrj4zvENkgALPDESaGn+R6MvpSarDrGeZc23aehlTOMngxse/C+eKqmfBf2/MniKBBq5RLxO3OHu35Bd+xZSAd/Q=="
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=debug msg="completed challenge"
Dec 08 09:50:30 volumio go-librespot[18376]: time="2025-12-08T09:50:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:30 volumio volumio[18215]: info: Loading i18n strings for locale en
Dec 08 09:50:30 volumio volumio[18215]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 08 09:50:30 volumio volumio[18215]: Updating browse sources language
Dec 08 09:50:30 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::initPlayerControls
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: Express server listening on port 3000
Dec 08 09:50:31 volumio volumio[18215]: [Metrics] WebUI: 14s 593.81ms
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::resetVolumioState
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::getcurrentVolume
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioRetrievevolume
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:31 volumio sudo[18400]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 08 09:50:31 volumio sudo[18400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:31 volumio sudo[18400]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:31 volumio sudo[18402]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 08 09:50:31 volumio sudo[18402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:31 volumio sudo[18402]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:31 volumio volumio[18215]: info: Volumio Network Manager: Network status updated: 1
Dec 08 09:50:31 volumio volumio[18215]: info: VolumeController:: Volume=86 Mute =false
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::pushState
Dec 08 09:50:31 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioPushState
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::updateTrackBlock
Dec 08 09:50:31 volumio volumio[18215]: info: CorePlayQueue::getTrackBlock
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioRetrievevolume
Dec 08 09:50:31 volumio volumio[18215]: info: Reloading queue from file
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::setRepeat null single undefined
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::pushState
Dec 08 09:50:31 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioPushState
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::setRandom null
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::pushState
Dec 08 09:50:31 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioPushState
Dec 08 09:50:31 volumio volumio[18215]: info: Setting Device type: Raspberry PI
Dec 08 09:50:31 volumio volumio[18215]: info: VolumeController:: Volume=86 Mute =false
Dec 08 09:50:31 volumio volumio[18215]: info: CoreStateMachine::pushState
Dec 08 09:50:31 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioPushState
Dec 08 09:50:31 volumio sudo[18415]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 08 09:50:31 volumio volumio[18215]: info: Completed loading Core Plugins
Dec 08 09:50:31 volumio sudo[18415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:31 volumio volumio[18215]: info: Preparing to generate the ALSA configuration file
Dec 08 09:50:31 volumio volumio[18215]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 08 09:50:31 volumio volumio[18215]: info: Discovery: Found device Volumio
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:31 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:31 volumio sudo[18415]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:31 volumio volumio[18215]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954
Dec 08 09:50:31 volumio volumio[18215]: info: Discovery: Found device Volumio
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:31 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:31 volumio volumio[18215]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 08 09:50:31 volumio volumio[18215]: info: Reading ALSA contributions from plugins.
Dec 08 09:50:31 volumio volumio[18215]: info: Upmpdcli Daemon Started
Dec 08 09:50:31 volumio volumio[18215]: info: Asound.conf file unchanged, so no further update is needed
Dec 08 09:50:31 volumio volumio[18215]: info: Output device has changed, restarting MPD
Dec 08 09:50:31 volumio volumio[18215]: info: Output device has changed, restarting Shairport Sync
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:31 volumio sudo[18418]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 08 09:50:31 volumio sudo[18418]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:31 volumio sudo[18420]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 08 09:50:31 volumio sudo[18420]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:31 volumio sudo[18418]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:31 volumio volumio[18215]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:50:31 volumio volumio[18215]: info: ___________ START PLUGINS ___________
Dec 08 09:50:31 volumio volumio[18215]: info: ControllerMpd::onStart: Initializing MPD
Dec 08 09:50:31 volumio volumio[18215]: info: Creating MPD Configuration file
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:31 volumio volumio[18215]: info: [1765209031649] CoreMusicLibrary::Adding element Media Servers
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:31 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 08 09:50:31 volumio sudo[18428]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 08 09:50:31 volumio sudo[18428]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:31 volumio sudo[18428]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:31 volumio sudo[18430]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 08 09:50:31 volumio sudo[18430]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:31 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 08 09:50:31 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 08 09:50:31 volumio systemd[1]: mpd.service: Consumed 4.521s CPU time.
Dec 08 09:50:31 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 08 09:50:31 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 08 09:50:31 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 08 09:50:31 volumio volumio[18215]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:31 volumio volumio[18215]: info: [1765209031785] CoreMusicLibrary::Adding element Last_100
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:31 volumio volumio[18215]: info: [1765209031790] CoreMusicLibrary::Adding element Webradio
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 08 09:50:31 volumio volumio[18215]: info: Initializing BBC Radios
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:31 volumio volumio[18215]: info: [1765209031862] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:31 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:31 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:31 volumio volumio[18215]: info: [1765209031874] CoreMusicLibrary::Adding element SoundCloud
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:31 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:31 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:31 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 08 09:50:31 volumio volumio[18215]: info: Creating Spotify config file
Dec 08 09:50:31 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio sudo[18455]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 08 09:50:32 volumio sudo[18455]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 08 09:50:32 volumio sudo[18455]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:32 volumio volumio[18215]: info: [squeezelite_mc] Starting proxy server...
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:32 volumio volumio[18215]: info: [1765209032239] CoreMusicLibrary::Adding element YouTube2
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube2
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:32 volumio volumio[18215]: info: [1765209032258] CoreMusicLibrary::Adding element YouTube Music
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube2
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube Music
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:32 volumio volumio[18215]: info: [1765209032271] CoreMusicLibrary::Adding element Podcast
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube2
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube Music
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Podcast
Dec 08 09:50:32 volumio volumio[18215]: info: Loading i18n strings for locale en
Dec 08 09:50:32 volumio volumio[18215]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 08 09:50:32 volumio volumio[18215]: Updating browse sources language
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube2
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube Music
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Podcast
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube2
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube Music
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Podcast
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:32 volumio volumio[18215]: info: [1765209032325] CoreMusicLibrary::Adding element Volusonic
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube2
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source YouTube Music
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Podcast
Dec 08 09:50:32 volumio volumio[18215]: Cannot find translation for source Volusonic
Dec 08 09:50:32 volumio volumio[18215]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 08 09:50:32 volumio volumio[18215]: info: Volumio Calling Home
Dec 08 09:50:32 volumio volumio-remote-updater[9752]: [2025-12-08 09:50:32] [connect] Successful connection
Dec 08 09:50:32 volumio volumio[18215]: info: [squeezelite_mc] Proxy server started on port 37473
Dec 08 09:50:32 volumio volumio[18215]: info: Preparing to generate the ALSA configuration file
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::volumioRetrievevolume
Dec 08 09:50:32 volumio volumio[18215]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 08 09:50:32 volumio volumio[18215]: info: Reading ALSA contributions from plugins.
Dec 08 09:50:32 volumio volumio[18215]: info: MPD Permissions set
Dec 08 09:50:32 volumio volumio[18215]: info: MPD Permissions set
Dec 08 09:50:32 volumio volumio-remote-updater[9752]: [2025-12-08 09:50:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765209032 101
Dec 08 09:50:32 volumio volumio[18215]: 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 08 09:50:32 volumio volumio[18215]: info: Spotify config file written
Dec 08 09:50:32 volumio sudo[18464]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 08 09:50:32 volumio sudo[18464]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:32 volumio volumio[18215]: 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 08 09:50:32 volumio volumio[18215]: info: VolumeController:: Volume=86 Mute =false
Dec 08 09:50:32 volumio volumio[18215]: info: CoreStateMachine::pushState
Dec 08 09:50:32 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::volumioPushState
Dec 08 09:50:32 volumio volumio[18215]: info: [squeezelite_mc] Server discovery started
Dec 08 09:50:32 volumio volumio[18215]: info: [squeezelite_mc] Player finder started
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio go-librespot[18466]: go-librespot daemon starting...
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:32 volumio volumio[18215]: info: No need to fix Spotify hosts
Dec 08 09:50:32 volumio sudo[18464]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:32 volumio go-librespot[18474]: time="2025-12-08T09:50:32-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:32 volumio go-librespot[18474]: time="2025-12-08T09:50:32-06:00" level=debug msg="app state loaded"
Dec 08 09:50:32 volumio go-librespot[18474]: time="2025-12-08T09:50:32-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:32 volumio go-librespot[18474]: time="2025-12-08T09:50:32-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:33 volumio volumio[18215]: 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 08 09:50:33 volumio volumio[18215]: info: Volumio called home
Dec 08 09:50:33 volumio volumio[18215]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 08 09:50:33 volumio volumio[18215]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 08 09:50:33 volumio volumio[18215]: 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 08 09:50:33 volumio volumio[18215]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 08 09:50:33 volumio volumio[18215]: SPOTIFY: BQBd8Kx1FXiN_z3a2lFuYM6IvBMmu83Zi4UEkKa7sjm2BMkQQf4XYoNVKDp5PHUEERC2yg5UAhgo3L_xrpWJUGw2EfVy1uSL82L514KtDhZfDe3o3SXIg5ODNM6qbr76w-Povju94hhpSal8XhWmAQUnOuyc-9XVW6v6UKGMJTWVfvCaD0oQCUmq3WkStimbay5zKKpPKFJmMUpLwELftgoKFgQL5nyXW4UIzOU
Dec 08 09:50:33 volumio volumio[18215]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 08 09:50:33 volumio volumio[18215]: info: New Spotify access token = BQBd8Kx1FXiN_z3a2lFuYM6IvBMmu83Zi4UEkKa7sjm2BMkQQf4XYoNVKDp5PHUEERC2yg5UAhgo3L_xrpWJUGw2EfVy1uSL82L514KtDhZfDe3o3SXIg5ODNM6qbr76w-Povju94hhpSal8XhWmAQUnOuyc-9XVW6v6UKGMJTWVfvCaD0oQCUmq3WkStimbay5zKKpPKFJmMUpLwELftgoKFgQL5nyXW4UIzOU
Dec 08 09:50:33 volumio volumio[18215]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 08 09:50:33 volumio volumio[18215]: 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 08 09:50:33 volumio volumio[18215]: info: Starting Shairport Sync
Dec 08 09:50:33 volumio volumio[18215]: info: Starting Shairport Sync
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-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 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-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 08 09:50:33 volumio volumio[18215]: info: Starting Shairport Sync
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-06:00" level=info msg="zeroconf server listening on port 44001"
Dec 08 09:50:33 volumio sudo[18490]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:50:33 volumio sudo[18490]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio sudo[18493]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:50:33 volumio sudo[18493]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio sudo[18494]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:50:33 volumio sudo[18494]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio volumio[18215]: info: Asound.conf file unchanged, so no further update is needed
Dec 08 09:50:33 volumio volumio[18215]: info: Output device has changed, restarting MPD
Dec 08 09:50:33 volumio sudo[18488]: 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 08 09:50:33 volumio sudo[18488]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-06:00" level=debug msg="obtained new client token: AAAL8tUDvVqxKKK4rOmGksHU/+9dkmAhWVizBEmCCG9EVssHBabQBbxs2544l+QmLecfJ8BPZmrb2g8T3P7MkpYyR97aqlt2uPeYCzI+9zDsa0PU987IHwjw66vhZ+MI8CxlAj9nmVONnMguM4jYcnr5NHf+NBuZYnFh/KWpiE6xYXf6U+pxfw1X7ayeCM0QhUBP9V98qZqrDtxjI/c7FQDzLB28KKtipyMmEKaG9RfRF8cAj6hy7r+fZQ=="
Dec 08 09:50:33 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 08 09:50:33 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 08 09:50:33 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:50:33 volumio systemd[1]: shairport-sync.service: Consumed 1.828s CPU time.
Dec 08 09:50:33 volumio sudo[18488]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio volumio[18215]: info: Output device has changed, restarting Shairport Sync
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:33 volumio sudo[18500]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 08 09:50:33 volumio sudo[18500]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio volumio[18215]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 08 09:50:33 volumio sudo[18500]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:33 volumio sudo[18502]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 08 09:50:33 volumio sudo[18502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:50:33 volumio sudo[18490]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-06:00" level=debug msg="completed challenge"
Dec 08 09:50:33 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 08 09:50:33 volumio go-librespot[18474]: time="2025-12-08T09:50:33-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:33 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 08 09:50:33 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 08 09:50:33 volumio systemd[1]: mpd.service: Consumed 1.516s CPU time.
Dec 08 09:50:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:33 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 08 09:50:33 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:50:33 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 08 09:50:33 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 08 09:50:33 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 08 09:50:33 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 08 09:50:33 volumio volumio[18215]: info: MPD Permissions set
Dec 08 09:50:33 volumio volumio[18215]: info: Shairport-Sync Started
Dec 08 09:50:33 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 08 09:50:33 volumio volumio[18215]: Error adding Membership: Error: addMembership EINVAL
Dec 08 09:50:33 volumio volumio[18215]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 08 09:50:33 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:50:33 volumio sudo[18493]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio sudo[18494]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio sudo[18519]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 08 09:50:33 volumio sudo[18519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio sudo[18519]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio volumio[18215]: 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 08 09:50:33 volumio volumio[18215]: info: Shairport-Sync Started
Dec 08 09:50:33 volumio volumio[18215]: info: Shairport-Sync Started
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:33 volumio sudo[18515]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 08 09:50:33 volumio sudo[18515]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 08 09:50:33 volumio sudo[18515]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio sudo[18537]: 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 08 09:50:33 volumio sudo[18537]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:33 volumio sudo[18537]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:33 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:33 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:33 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true
Dec 08 09:50:34 volumio volumio[18215]: info: Starting Shairport Sync
Dec 08 09:50:34 volumio sudo[18547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 08 09:50:34 volumio sudo[18547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:34 volumio volumio[18215]: 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 08 09:50:34 volumio sudo[18549]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 08 09:50:34 volumio sudo[18549]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:34 volumio volumio[18215]: info: Spotify Successfully logged in
Dec 08 09:50:34 volumio volumio[18215]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 08 09:50:34 volumio volumio[18215]: info: [1765209034070] CoreMusicLibrary::Adding element Spotify
Dec 08 09:50:34 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 08 09:50:34 volumio volumio[18215]: Cannot find translation for source Bandcamp Discover
Dec 08 09:50:34 volumio volumio[18215]: Cannot find translation for source SoundCloud
Dec 08 09:50:34 volumio volumio[18215]: Cannot find translation for source YouTube2
Dec 08 09:50:34 volumio volumio[18215]: Cannot find translation for source YouTube Music
Dec 08 09:50:34 volumio volumio[18215]: Cannot find translation for source Podcast
Dec 08 09:50:34 volumio volumio[18215]: Cannot find translation for source Volusonic
Dec 08 09:50:34 volumio volumio[18215]: Cannot find translation for source Spotify
Dec 08 09:50:34 volumio systemd[1]: Reloading.
Dec 08 09:50:34 volumio volumio[18215]: info: [squeezelite_mc] Notification listener started
Dec 08 09:50:34 volumio volumio[18215]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 08 09:50:34 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:34 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:34 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 08 09:50:34 volumio volumio[18215]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 08 09:50:35 volumio volumio[18215]: 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 08 09:50:35 volumio volumio[18215]: 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 08 09:50:35 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 08 09:50:35 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 08 09:50:36 volumio sudo[18547]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:36 volumio volumio[18215]: info: go-librespot daemon successfully initialized
Dec 08 09:50:36 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:50:36 volumio sudo[18570]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:50:36 volumio sudo[18570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:36 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 08 09:50:36 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 08 09:50:36 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:50:36 volumio systemd[1]: shairport-sync.service: Consumed 1.499s CPU time.
Dec 08 09:50:36 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:36 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:36 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 08 09:50:36 volumio sudo[18549]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:36 volumio volumio[18215]: info: Shairport-Sync Started
Dec 08 09:50:36 volumio sudo[18570]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:36 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 08 09:50:36 volumio sudo[18586]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 08 09:50:36 volumio sudo[18586]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:36 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 08 09:50:36 volumio volumio[18215]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 08 09:50:36 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:36 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44.
Dec 08 09:50:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:36 volumio go-librespot[18590]: go-librespot daemon starting...
Dec 08 09:50:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:36 volumio go-librespot[18591]: time="2025-12-08T09:50:36-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:36 volumio go-librespot[18591]: time="2025-12-08T09:50:36-06:00" level=debug msg="app state loaded"
Dec 08 09:50:36 volumio go-librespot[18591]: time="2025-12-08T09:50:36-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:36 volumio go-librespot[18591]: time="2025-12-08T09:50:36-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:36 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 08 09:50:36 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 08 09:50:36 volumio sudo[18586]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:37 volumio go-librespot[18591]: time="2025-12-08T09:50:37-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 08 09:50:37 volumio go-librespot[18591]: time="2025-12-08T09:50:37-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 08 09:50:37 volumio go-librespot[18591]: time="2025-12-08T09:50:37-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 08 09:50:37 volumio go-librespot[18591]: time="2025-12-08T09:50:37-06:00" level=info msg="zeroconf server listening on port 36769"
Dec 08 09:50:37 volumio go-librespot[18591]: time="2025-12-08T09:50:37-06:00" level=debug msg="obtained new client token: AABNyq+23xz7Sk/yClBYmZAqo4VC+tBlGV5tyFp6m9mR9aMEttjuW7AeRMteFrOdf8Z9uaxYt6DO0equNzRyhuJ5TynwM4r+K67gQ2IonA+ArQLQsh3708O7B1L6trihex/HyiNmflaoTxHrA/3HOmv1cTYabStFv7Q8HScC4ii1GcW2kPinLvs5EmwKbKGq5IgpZEho9p8qwYRWf3y3a087iv7NnngTZYWHb5aWA4XCP9VzPxtPa6g="
Dec 08 09:50:37 volumio go-librespot[18591]: time="2025-12-08T09:50:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:37 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:50:37 volumio sudo[18599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:50:37 volumio sudo[18599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:37 volumio sudo[18599]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:37 volumio volumio[18215]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 08 09:50:37 volumio sudo[18603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 08 09:50:37 volumio sudo[18603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:37 volumio sudo[18603]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:37 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 08 09:50:37 volumio sudo[18606]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 08 09:50:37 volumio sudo[18606]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:37 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 08 09:50:37 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 08 09:50:37 volumio mpd[18544]: 2025-12-08T09:50:37 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 08 09:50:37 volumio sudo[18606]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:37 volumio volumio[18215]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 08 09:50:37 volumio volumio[18215]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 08 09:50:37 volumio volumio[18215]: 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 08 09:50:37 volumio volumio[18215]: 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 08 09:50:37 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 08 09:50:37 volumio sudo[18420]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:37 volumio sudo[18502]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:37 volumio sudo[18430]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:38 volumio volumio[18215]: error: MPD error: The expression evaluated to a falsy value:
Dec 08 09:50:38 volumio volumio[18215]: assert.ok(self.idling)
Dec 08 09:50:38 volumio volumio[18215]: error: The expression evaluated to a falsy value:
Dec 08 09:50:38 volumio volumio[18215]: assert.ok(self.idling)
Dec 08 09:50:38 volumio volumio[18215]: error: MPD error: The expression evaluated to a falsy value:
Dec 08 09:50:38 volumio volumio[18215]: assert.ok(self.idling)
Dec 08 09:50:38 volumio volumio[18215]: error: The expression evaluated to a falsy value:
Dec 08 09:50:38 volumio volumio[18215]: assert.ok(self.idling)
Dec 08 09:50:38 volumio volumio[18215]: info: MPD running with PID18544
Dec 08 09:50:38 volumio volumio[18215]: ,establishing connection
Dec 08 09:50:38 volumio volumio[18215]: error: updateQueue error: null
Dec 08 09:50:38 volumio volumio[18215]: error: updateQueue error: null
Dec 08 09:50:38 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:50:38 volumio sudo[18617]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:50:38 volumio sudo[18617]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:38 volumio sudo[18617]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:38 volumio go-librespot[18591]: time="2025-12-08T09:50:38-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:38 volumio go-librespot[18591]: time="2025-12-08T09:50:38-06:00" level=debug msg="completed challenge"
Dec 08 09:50:38 volumio go-librespot[18591]: time="2025-12-08T09:50:38-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 08 09:50:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:38 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:50:38 volumio sudo[18620]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:50:38 volumio sudo[18620]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:38 volumio sudo[18620]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:38 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:38 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:39 volumio volumio[18215]: info: Initializing connection to go-librespot Websocket
Dec 08 09:50:39 volumio volumio[18215]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 08 09:50:39 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:50:39 volumio sudo[18637]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:50:39 volumio sudo[18637]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:39 volumio sudo[18637]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:40 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:50:40 volumio sudo[18643]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:50:40 volumio sudo[18643]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:40 volumio sudo[18643]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:40 volumio volumio[18215]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 08 09:50:40 volumio sudo[18646]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 08 09:50:40 volumio sudo[18646]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:40 volumio sudo[18646]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:40 volumio volumio[18215]: info: Completed starting Core Plugins
Dec 08 09:50:40 volumio volumio[18215]: info: -------------------------------------------
Dec 08 09:50:40 volumio volumio[18215]: info: ----- MyVolumio plugins startup ----
Dec 08 09:50:40 volumio volumio[18215]: info: -------------------------------------------
Dec 08 09:50:40 volumio volumio[18215]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 08 09:50:41 volumio sudo[18649]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:50:41 volumio sudo[18649]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:41 volumio sudo[18651]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:50:41 volumio sudo[18651]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:41 volumio sudo[18653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 08 09:50:41 volumio sudo[18653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 08 09:50:41 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 08 09:50:41 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 08 09:50:41 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 08 09:50:41 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 08 09:50:41 volumio sudo[18651]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:41 volumio mpd_monitor.sh[18657]: MPD Monitor Service: Starting MPD Monitor Service
Dec 08 09:50:41 volumio sudo[18653]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:41 volumio sudo[18649]: pam_unix(sudo:session): session closed for user root
Dec 08 09:50:41 volumio volumio[18215]: info: Successfully started MPD Monitor
Dec 08 09:50:41 volumio volumio[18215]: info: Successfully started MPD Monitor
Dec 08 09:50:41 volumio volumio[18215]: info: Successfully started MPD Monitor
Dec 08 09:50:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 45.
Dec 08 09:50:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:41 volumio go-librespot[18661]: go-librespot daemon starting...
Dec 08 09:50:41 volumio go-librespot[18662]: time="2025-12-08T09:50:41-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:41 volumio go-librespot[18662]: time="2025-12-08T09:50:41-06:00" level=debug msg="app state loaded"
Dec 08 09:50:41 volumio go-librespot[18662]: time="2025-12-08T09:50:41-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:41 volumio go-librespot[18662]: time="2025-12-08T09:50:41-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-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 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-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 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-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 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-06:00" level=info msg="zeroconf server listening on port 37223"
Dec 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-06:00" level=debug msg="obtained new client token: AAAdIisvAT4C1MFdwOk98WEfrgZrK38Xq4yx5/j4xWs9LD9y7RZZ7swI6ze3m4yzbxrcy+CPZWTeFjrVQrfoxxKJRySC/mHx6SEG/n1DCsBfZDWXgZAUtg37HsujyRFwrwOsYBI0A9UhQD3+3iahGyI0rXOuRzo4OvVC0tD+KbA/IG1ZdWL28omc0EvAKqbzoT1t1CfNgzQd4N45a043PFCYZtgzJX++u6M7/L69voEwXjiSxeRX17Q="
Dec 08 09:50:42 volumio volumio[18215]: info: Initializing connection to go-librespot Websocket
Dec 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-06:00" level=debug msg="new websocket client"
Dec 08 09:50:42 volumio volumio[18215]: info: Connection to go-librespot Websocket established
Dec 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-06:00" level=debug msg="completed challenge"
Dec 08 09:50:42 volumio go-librespot[18662]: time="2025-12-08T09:50:42-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:42 volumio volumio[18215]: info: Connection to go-librespot Websocket closed
Dec 08 09:50:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46.
Dec 08 09:50:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 08 09:50:45 volumio go-librespot[18669]: go-librespot daemon starting...
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=info msg="running go-librespot 0.4.0"
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=debug msg="app state loaded"
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=debug msg="stored credentials not found"
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-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 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-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 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=info msg="zeroconf server listening on port 34071"
Dec 08 09:50:45 volumio volumio[18215]: info: Getting Spotify volume
Dec 08 09:50:45 volumio volumio[18215]: info: Initializing connection to go-librespot Websocket
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=debug msg="new websocket client"
Dec 08 09:50:45 volumio volumio[18215]: 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 08 09:50:45 volumio volumio[18215]: info: Connection to go-librespot Websocket established
Dec 08 09:50:45 volumio go-librespot[18670]: time="2025-12-08T09:50:45-06:00" level=debug msg="obtained new client token: AAAeEkrXJ0y10iZyS8cpifGeu8xoflBgdjHPILDzhnLlS/o51VU4u/VgFxWJ1ZwChTQlmrj3mvbcK54/R/yrwfj2BCB11MXqgYqW/17Xh+X2+djdDxHZO1D9cgMDOfpgGkDZzS2P+/fe2EraBaKInNzUnnBB/+X3OFL4UsS7iv+mFS9Sk1gvgF6xRuzBRXIn7wSluG9XonG64vLZYScE9fR6A3MByG7U0IpAJOmly7a4favObl4dIvbwxw=="
Dec 08 09:50:45 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:45 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:45 volumio volumio[18215]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86
Dec 08 09:50:45 volumio volumio[18215]: SPOTIFY: SPOTIFY VOLUME undefined
Dec 08 09:50:45 volumio volumio[18215]: SPOTIFY: VOLUMIO VOLUME 86
Dec 08 09:50:45 volumio volumio[18215]: info: Aligning Spotify Volume to Volumio Volume
Dec 08 09:50:45 volumio volumio[18215]: info: CoreCommandRouter::volumioGetState
Dec 08 09:50:45 volumio volumio[18215]: info: CorePlayQueue::getTrack 0
Dec 08 09:50:45 volumio volumio[18215]: info: Setting Spotify Volume from Volumio: 86
Dec 08 09:50:46 volumio go-librespot[18670]: time="2025-12-08T09:50:46-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 08 09:50:46 volumio go-librespot[18670]: time="2025-12-08T09:50:46-06:00" level=debug msg="completed keyexchange"
Dec 08 09:50:46 volumio go-librespot[18670]: time="2025-12-08T09:50:46-06:00" level=debug msg="completed challenge"
Dec 08 09:50:46 volumio go-librespot[18670]: time="2025-12-08T09:50:46-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 08 09:50:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 08 09:50:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 08 09:50:46 volumio volumio[18215]: info: Connection to go-librespot Websocket closed
Dec 08 09:50:46 volumio volumio[18215]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 08 09:50:46 volumio volumio[18215]: Error: socket hang up
Dec 08 09:50:46 volumio volumio[18215]: at connResetException (node:internal/errors:720:14)
Dec 08 09:50:46 volumio volumio[18215]: at Socket.socketOnEnd (node:_http_client:519:23)
Dec 08 09:50:46 volumio volumio[18215]: at Socket.emit (node:events:526:35)
Dec 08 09:50:46 volumio volumio[18215]: at endReadableNT (node:internal/streams/readable:1376:12)
Dec 08 09:50:46 volumio volumio[18215]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 08 09:50:46 volumio volumio[18215]: code: 'ECONNRESET',
Dec 08 09:50:46 volumio volumio[18215]: response: undefined
Dec 08 09:50:46 volumio volumio[18215]: }
Dec 08 09:50:46 volumio volumio[18215]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 08 09:50:46 volumio sudo[18692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 09:49'
Dec 08 09:50:46 volumio sudo[18692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)"
NAME="Raspbian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
VOLUMIO_BUILD_VERSION="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"