Dec 30 17:56:00 volumio volumio[20473]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:00 volumio sudo[21097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:00 volumio sudo[21097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:00 volumio sudo[21097]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:00 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.25.83 Dec 30 17:56:00 volumio avahi-daemon[664]: Registering new address record for 169.254.25.83 on eth0.IPv4. Dec 30 17:56:00 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:00 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.25.83 Dec 30 17:56:00 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:00 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:00 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 30 17:56:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:00 volumio go-librespot[21115]: go-librespot daemon starting... Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="app state loaded" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:01 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.25.83 Dec 30 17:56:01 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.25.83 Dec 30 17:56:01 volumio avahi-daemon[664]: Withdrawing address record for 169.254.25.83 on eth0. Dec 30 17:56:01 volumio volumio[20473]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:01 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:01 volumio sudo[21128]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:01 volumio sudo[21128]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:01 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:01 volumio sudo[21128]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=info msg="zeroconf server listening on port 35999" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="obtained new client token: AAAEX27L1GUZvuwUqnmOgFHgdLlQsYEFkRO9ezrriJ+OyRp5nWZdLA/Xubv2IibtwIBnx+iLoW1x57EanldCT/CZo/DtA5zIkU3qi7paBxe1stFuXOFIBZfr33YdU5R6phK25uL7e27rZ8jmICekEhunW7u+Kg7vhpqN36v+7+FS079gqqxJaHYgrXhTz2xNZI55zH16bUEqXn2aWDG0zZGTPGlxbTjE7V1X3YDxsqp6QYIE5fc2YLFVpQ==" Dec 30 17:56:01 volumio volumio[20473]: info: Initializing connection to go-librespot Websocket Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="new websocket client" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:01 volumio volumio[20473]: info: Connection to go-librespot Websocket established Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=debug msg="completed challenge" Dec 30 17:56:01 volumio go-librespot[21116]: time="2025-12-30T17:56:01-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:01 volumio volumio[20473]: info: Connection to go-librespot Websocket closed Dec 30 17:56:01 volumio volumio[20473]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:01 volumio sudo[21143]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:01 volumio sudo[21143]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:01 volumio sudo[21146]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 17:56:01 volumio sudo[21146]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:01 volumio sudo[21143]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:01 volumio sudo[21148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 17:56:01 volumio sudo[21148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:01 volumio volumio[20473]: info: Completed starting Core Plugins Dec 30 17:56:01 volumio volumio[20473]: info: ------------------------------------------- Dec 30 17:56:01 volumio volumio[20473]: info: ----- MyVolumio plugins startup ---- Dec 30 17:56:01 volumio volumio[20473]: info: ------------------------------------------- Dec 30 17:56:01 volumio volumio[20473]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 17:56:01 volumio sudo[21151]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 17:56:01 volumio sudo[21151]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:02 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 17:56:02 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 17:56:02 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 17:56:02 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 17:56:02 volumio sudo[21151]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:02 volumio sudo[21146]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:02 volumio sudo[21148]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:02 volumio mpd_monitor.sh[21154]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 17:56:02 volumio volumio[20473]: info: Successfully started MPD Monitor Dec 30 17:56:02 volumio volumio[20473]: info: Successfully started MPD Monitor Dec 30 17:56:02 volumio volumio[20473]: info: Successfully started MPD Monitor Dec 30 17:56:04 volumio volumio[20473]: info: Getting Spotify volume Dec 30 17:56:04 volumio volumio[20473]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 17:56:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 30 17:56:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:04 volumio volumio[20473]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 17:56:04 volumio volumio[20473]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 17:56:04 volumio volumio[20473]: errno: -111, Dec 30 17:56:04 volumio volumio[20473]: code: 'ECONNREFUSED', Dec 30 17:56:04 volumio volumio[20473]: syscall: 'connect', Dec 30 17:56:04 volumio volumio[20473]: address: '127.0.0.1', Dec 30 17:56:04 volumio volumio[20473]: port: 9879, Dec 30 17:56:04 volumio volumio[20473]: response: undefined Dec 30 17:56:04 volumio volumio[20473]: } Dec 30 17:56:04 volumio volumio[20473]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 17:56:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:05 volumio go-librespot[21172]: go-librespot daemon starting... Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="app state loaded" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=info msg="zeroconf server listening on port 34719" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="obtained new client token: AAA3zroI9lX6wSPtmTKPAVrelY4vn0BO3WeTpVs0l45rls8q8PM8spd1sY5A9dhASr9eFH0R4a8oJxle7/V0ySOcZPaVOoTJ3TvSsfioBNMu/y2tmv44BIZsDArLcLsNedTImEJnDKW8+S+aO+iCVBNSKI/Sgqo+Lnoy6Saa7y2+lE8Q7Kw7JXQ1joHfonNUo8ELOB8qh6dIOD9sC8LRzPgVfCOKJuHB22FbDGd6VoHCpo1KOt4Pz9qT7g==" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=debug msg="completed challenge" Dec 30 17:56:05 volumio go-librespot[21176]: time="2025-12-30T17:56:05-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:06 volumio sudo[21195]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 17:55' Dec 30 17:56:06 volumio sudo[21195]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:06 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.79.132 Dec 30 17:56:06 volumio avahi-daemon[664]: Registering new address record for 169.254.79.132 on eth0.IPv4. Dec 30 17:56:06 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:06 volumio sudo[21195]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:06 volumio volumio-remote-updater[702]: [2025-12-30 17:56:06] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 17:56:06 volumio volumio-remote-updater[702]: [2025-12-30 17:56:06] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 17:56:06 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:07 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 17:56:07 volumio systemd[1]: volumio.service: Consumed 49.897s CPU time. Dec 30 17:56:07 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 17:56:07 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 17:56:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.79.132 Dec 30 17:56:07 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1141. Dec 30 17:56:07 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 17:56:07 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 17:56:07 volumio systemd[1]: volumio.service: Consumed 49.897s CPU time. Dec 30 17:56:07 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 17:56:07 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 17:56:07 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.79.132 Dec 30 17:56:07 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.79.132 Dec 30 17:56:07 volumio avahi-daemon[664]: Withdrawing address record for 169.254.79.132 on eth0. Dec 30 17:56:07 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:07 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:07 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:07 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:07 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Dec 30 17:56:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:08 volumio go-librespot[21254]: go-librespot daemon starting... Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="app state loaded" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=info msg="zeroconf server listening on port 44329" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="obtained new client token: AAAp274+D7zJlYNLFcNeJVB0lfLMCedb/f2kOKrTFk0wS/hT+0pxI4mbMHMEuWPdSPlykqRlCGT4gQpYtPLSwaFM09v+21pets8qBOMCD0xrNwxyS0MbV3eh16Ae9ld8GBPn2U+sbGNozIcWiRiNGWw98XUrZ94NTjVn6vXnUT9pA0UfudJsYrew3wgE+3Bg2esLoCcuv2Ch6+X6LwtH+YdPVf8DEJw/dHsXlLcI1oLiVX20TGpGUFsklQ==" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=debug msg="completed challenge" Dec 30 17:56:09 volumio go-librespot[21255]: time="2025-12-30T17:56:09-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:09 volumio volumio[21223]: info: ------------------------------------------- Dec 30 17:56:09 volumio volumio[21223]: info: ----- Volumio3 ---- Dec 30 17:56:09 volumio volumio[21223]: info: ------------------------------------------- Dec 30 17:56:09 volumio volumio[21223]: info: ----- System startup ---- Dec 30 17:56:09 volumio volumio[21223]: info: ------------------------------------------- Dec 30 17:56:10 volumio volumio[21223]: info: MYVOLUMIO Environment detected Dec 30 17:56:10 volumio volumio[21223]: info: Plugin folders cleanup Dec 30 17:56:10 volumio volumio[21223]: info: Scanning into folder /volumio/app/plugins/ Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category audio_interface Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category miscellanea Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category music_service Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category plugins.json Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category system_controller Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category user_interface Dec 30 17:56:10 volumio volumio[21223]: info: Scanning into folder /data/plugins/ Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category audio_interface Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category music_service Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category system_controller Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category system_hardware Dec 30 17:56:10 volumio volumio[21223]: info: Scanning category user_interface Dec 30 17:56:10 volumio volumio[21223]: info: Plugin folders cleanup completed Dec 30 17:56:10 volumio volumio[21223]: info: ------------------------------------------- Dec 30 17:56:10 volumio volumio[21223]: info: ----- Core plugins startup ---- Dec 30 17:56:10 volumio volumio[21223]: info: ------------------------------------------- Dec 30 17:56:10 volumio volumio[21223]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 17:56:10 volumio volumio[21223]: info: Adding plugin upnp to MyMusic Plugins Dec 30 17:56:10 volumio volumio[21223]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 17:56:10 volumio volumio[21223]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 17:56:10 volumio volumio[21223]: info: Loading plugins from folder /data/plugins/ Dec 30 17:56:10 volumio volumio[21223]: info: Loading plugin "system"... Dec 30 17:56:10 volumio volumio[21223]: info: Loading plugin "appearance"... Dec 30 17:56:11 volumio volumio[21223]: info: Loading plugin "network"... Dec 30 17:56:11 volumio volumio[21223]: info: Refreshing Cached IP Addresses Dec 30 17:56:11 volumio sudo[21277]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 17:56:11 volumio sudo[21277]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:11 volumio sudo[21279]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 17:56:11 volumio sudo[21277]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:11 volumio volumio[21223]: info: Loading plugin "services"... Dec 30 17:56:11 volumio sudo[21279]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:11 volumio volumio[21223]: info: Loading plugin "alsa_controller"... Dec 30 17:56:11 volumio sudo[21279]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:11 volumio sudo[21287]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 17:56:11 volumio sudo[21287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:11 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 17:56:11 volumio volumio[21223]: info: Loading plugin "wizard"... Dec 30 17:56:11 volumio volumio[21223]: info: Loading plugin "networkfs"... Dec 30 17:56:11 volumio volumio[21223]: info: Starting Udev Watcher for removable devices Dec 30 17:56:11 volumio volumio[21223]: info: Ignoring mount for partition: boot Dec 30 17:56:11 volumio volumio[21223]: info: Ignoring mount for partition: volumio Dec 30 17:56:11 volumio volumio[21223]: info: Ignoring mount for partition: volumio_data Dec 30 17:56:11 volumio volumio-remote-updater[702]: [2025-12-30 17:56:11] [connect] Successful connection Dec 30 17:56:11 volumio volumio[21223]: info: Mounting Device Wikipedia Dec 30 17:56:12 volumio sudo[21316]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 17:56:12 volumio sudo[21316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:12 volumio sudo[21316]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:12 volumio volumio[21223]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 17:56:12 volumio volumio[21223]: dmesg(1) may have more information after failed mount system call. Dec 30 17:56:12 volumio volumio[21223]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 17:56:12 volumio volumio[21223]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 17:56:12 volumio volumio[21223]: dmesg(1) may have more information after failed mount system call. Dec 30 17:56:12 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 17:56:12 volumio volumio[21223]: info: Loading plugin "volumio_command_line_client"... Dec 30 17:56:12 volumio volumio[21223]: info: Loading plugin "upnp"... Dec 30 17:56:12 volumio volumio[21223]: info: [1767138972102] Starting Upmpd Daemon Dec 30 17:56:12 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 17:56:12 volumio volumio[21223]: info: Loading plugin "my_music"... Dec 30 17:56:12 volumio volumio[21223]: info: Loading plugin "mpd"... Dec 30 17:56:12 volumio sudo[21287]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Dec 30 17:56:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:12 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.250.73 Dec 30 17:56:12 volumio avahi-daemon[664]: Registering new address record for 169.254.250.73 on eth0.IPv4. Dec 30 17:56:12 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:12 volumio volumio[21223]: info: Loading plugin "upnp_browser"... Dec 30 17:56:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:12 volumio go-librespot[21318]: go-librespot daemon starting... Dec 30 17:56:12 volumio go-librespot[21334]: time="2025-12-30T17:56:12-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:12 volumio go-librespot[21334]: time="2025-12-30T17:56:12-06:00" level=debug msg="app state loaded" Dec 30 17:56:12 volumio go-librespot[21334]: time="2025-12-30T17:56:12-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:12 volumio go-librespot[21334]: time="2025-12-30T17:56:12-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:12 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:12 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:12 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:12 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.250.73 Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=info msg="zeroconf server listening on port 36525" Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=debug msg="obtained new client token: AAA3mLIvX5nyaT6zYeCTIV+RXhKn16kfl05GTy920yB3NVRURjoCxk0zq5GhqytHLxaSiHdsha99xqXPGdv1HP6vqbzv/li0LeyZmAhllrZUrI3EqhgysCWrVhPjZDg3rGhsnz56gXNjsDpnDSM1uppLgozPMg+iqc6ll3Oz2cE49z0uujYy6wmhmkAhhhcc3RpcraHKJhLDHdbJ+EG5IiNqscZTETqsUne8a2o8nYgcmvDwOabHqZH48Q==" Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:13 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.250.73 Dec 30 17:56:13 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.250.73 Dec 30 17:56:13 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:13 volumio avahi-daemon[664]: Withdrawing address record for 169.254.250.73 on eth0. Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=debug msg="completed challenge" Dec 30 17:56:13 volumio go-librespot[21334]: time="2025-12-30T17:56:13-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:13 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:13 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:13 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:13 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:15 volumio volumio[21223]: info: Loading plugin "alarm-clock"... Dec 30 17:56:15 volumio volumio[21223]: info: Loading plugin "airplay_emulation"... Dec 30 17:56:15 volumio volumio[21223]: info: Starting Shairport Sync Dec 30 17:56:15 volumio volumio[21223]: info: Loading plugin "last_100"... Dec 30 17:56:15 volumio volumio[21223]: info: Loading plugin "webradio"... Dec 30 17:56:15 volumio volumio[21223]: info: Loading plugin "i2s_dacs"... Dec 30 17:56:15 volumio volumio[21223]: info: I2S DAC not set, start Auto-detection Dec 30 17:56:15 volumio volumio[21223]: info: Loading plugin "volumiodiscovery"... Dec 30 17:56:15 volumio volumio[21223]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 17:56:15 volumio volumio[21223]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:56:15 volumio volumio[21223]: *** WARNING *** For more information see Dec 30 17:56:15 volumio volumio[21223]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 17:56:15 volumio volumio[21223]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:56:15 volumio volumio[21223]: *** WARNING *** For more information see Dec 30 17:56:15 volumio node[21223]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 17:56:15 volumio node[21223]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:56:15 volumio node[21223]: *** WARNING *** For more information see Dec 30 17:56:15 volumio node[21223]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 17:56:15 volumio node[21223]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:56:15 volumio node[21223]: *** WARNING *** For more information see Dec 30 17:56:15 volumio volumio[21223]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 17:56:15 volumio volumio[21223]: info: Discovery: Started advertising with name: Volumio Dec 30 17:56:15 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 17:56:15 volumio volumio[21223]: info: Loading plugin "bandcamp"... Dec 30 17:56:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Dec 30 17:56:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:16 volumio go-librespot[21360]: go-librespot daemon starting... Dec 30 17:56:16 volumio go-librespot[21361]: time="2025-12-30T17:56:16-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:16 volumio go-librespot[21361]: time="2025-12-30T17:56:16-06:00" level=debug msg="app state loaded" Dec 30 17:56:16 volumio go-librespot[21361]: time="2025-12-30T17:56:16-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:16 volumio go-librespot[21361]: time="2025-12-30T17:56:16-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-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 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-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 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-06:00" level=info msg="zeroconf server listening on port 38405" Dec 30 17:56:17 volumio volumio[21223]: info: Plugin calmradio is not enabled Dec 30 17:56:17 volumio volumio[21223]: info: Loading plugin "soundcloud"... Dec 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-06:00" level=debug msg="obtained new client token: AAAbABbkKHHxI+dmhdqud9n4McuJavOlBDF2JcD62oIhNM21p9E64DdO/UlLbYcbmhs/L8aegCYgLQGJ+hENb0A8U9GTpGkrJP74CADNxyRyYk5DRhFa7NTHRoNIyF1rKoMTQ5/SW4XgdblepYSQwNkS9gF1f/Gtv3hfVss4opJaFY7si0YiaLF2L0w89zE8ReRHnGgYEb3AJ9w7AZNuNU6/u1e7PipbgeqrqCC8Yvhxlj1MS9jkuCA=" Dec 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-06:00" level=debug msg="completed challenge" Dec 30 17:56:17 volumio go-librespot[21361]: time="2025-12-30T17:56:17-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:17 volumio volumio[21223]: info: Loading plugin "spop"... Dec 30 17:56:18 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 17:56:18 volumio volumio[21223]: info: Loading plugin "squeezelite_mc"... Dec 30 17:56:19 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.120.160 Dec 30 17:56:19 volumio avahi-daemon[664]: Registering new address record for 169.254.120.160 on eth0.IPv4. Dec 30 17:56:19 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:19 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:19 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:19 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:19 volumio volumio[21223]: info: Loading plugin "youtube2"... Dec 30 17:56:19 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.120.160 Dec 30 17:56:19 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.120.160 Dec 30 17:56:19 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.120.160 Dec 30 17:56:19 volumio avahi-daemon[664]: Withdrawing address record for 169.254.120.160 on eth0. Dec 30 17:56:19 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:19 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:19 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:19 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:19 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:19 volumio volumio[21223]: info: Loading plugin "ytcr"... Dec 30 17:56:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7. Dec 30 17:56:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:20 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 17:56:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:20 volumio go-librespot[21401]: go-librespot daemon starting... Dec 30 17:56:20 volumio go-librespot[21402]: time="2025-12-30T17:56:20-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:20 volumio go-librespot[21402]: time="2025-12-30T17:56:20-06:00" level=debug msg="app state loaded" Dec 30 17:56:20 volumio go-librespot[21402]: time="2025-12-30T17:56:20-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:20 volumio go-librespot[21402]: time="2025-12-30T17:56:20-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:20 volumio go-librespot[21402]: time="2025-12-30T17:56:20-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:20 volumio go-librespot[21402]: time="2025-12-30T17:56:20-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 30 17:56:20 volumio go-librespot[21402]: time="2025-12-30T17:56:20-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 30 17:56:21 volumio go-librespot[21402]: time="2025-12-30T17:56:21-06:00" level=info msg="zeroconf server listening on port 35029" Dec 30 17:56:21 volumio go-librespot[21402]: time="2025-12-30T17:56:21-06:00" level=debug msg="obtained new client token: AAAq3RFYgvi1C8UFHHNfIzkbwuvdxnCKFYf/tTSmkCNsI30D9oSzar7Aae9SxONSPGT2ORIun5VQc/VKK6tVjQmxz4cjMgapdJUO/Um+6stw0ElDWbvug1d9X/ZFr79gWQ0Jac/xd/4ptbKzgkZeObHUwrX+0K/5SeNejY8jRte8Flpqf71zNRHdNtDgTOlbKzpcb3Z0cVBFc+3sCINAhseKe9f3Ks2SYOHoSy6/S9feyI/z8uZR1rk=" Dec 30 17:56:21 volumio go-librespot[21402]: time="2025-12-30T17:56:21-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:21 volumio go-librespot[21402]: time="2025-12-30T17:56:21-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:21 volumio go-librespot[21402]: time="2025-12-30T17:56:21-06:00" level=debug msg="completed challenge" Dec 30 17:56:21 volumio go-librespot[21402]: time="2025-12-30T17:56: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 30 17:56:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:22 volumio volumio[21223]: info: Loading plugin "ytmusic"... Dec 30 17:56:23 volumio volumio[21223]: info: Plugin now_playing is not enabled Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "outputs"... Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "albumart"... Dec 30 17:56:23 volumio volumio[21223]: info: Plugin example_plugin is not enabled Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "inputs"... Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "updater_comm"... Dec 30 17:56:23 volumio volumio[21223]: info: Plugin mpdemulation is not enabled Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "rest_api"... Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "websocket"... Dec 30 17:56:23 volumio volumio[21223]: info: Starting Socket.io Server version 1.7.4 Dec 30 17:56:23 volumio volumio[21223]: info: Plugin fusiondsp is not enabled Dec 30 17:56:23 volumio volumio[21223]: info: Plugin mpdoutput is not enabled Dec 30 17:56:23 volumio volumio[21223]: info: Plugin RoonBridge is not enabled Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "podcast"... Dec 30 17:56:23 volumio volumio[21223]: info: ControllerPodcast::constructor Dec 30 17:56:23 volumio volumio[21223]: info: Loading plugin "volusonic"... Dec 30 17:56:23 volumio volumio[21427]: Forking 3 albumart workers Dec 30 17:56:24 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.82.16 Dec 30 17:56:24 volumio avahi-daemon[664]: Registering new address record for 169.254.82.16 on eth0.IPv4. Dec 30 17:56:24 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8. Dec 30 17:56:24 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:24 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:24 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:24 volumio go-librespot[21483]: go-librespot daemon starting... Dec 30 17:56:24 volumio volumio-remote-updater[702]: [2025-12-30 17:56:24] [connect] Successful connection Dec 30 17:56:24 volumio go-librespot[21484]: time="2025-12-30T17:56:24-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:24 volumio go-librespot[21484]: time="2025-12-30T17:56:24-06:00" level=debug msg="app state loaded" Dec 30 17:56:24 volumio go-librespot[21484]: time="2025-12-30T17:56:24-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:24 volumio go-librespot[21484]: time="2025-12-30T17:56:24-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:24 volumio go-librespot[21484]: time="2025-12-30T17:56:24-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:24 volumio go-librespot[21484]: time="2025-12-30T17:56:24-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 30 17:56:24 volumio go-librespot[21484]: time="2025-12-30T17:56:24-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 30 17:56:25 volumio go-librespot[21484]: time="2025-12-30T17:56:25-06:00" level=info msg="zeroconf server listening on port 43539" Dec 30 17:56:25 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.82.16 Dec 30 17:56:25 volumio go-librespot[21484]: time="2025-12-30T17:56:25-06:00" level=debug msg="obtained new client token: AABoqmHEvgL+wycLnqutkVrkYp2Sm/amJo7jevyWzZrC/zuDogMWQLFma+iadW58ZRPGMMRQW7gyFjqK1r4z1nRdLNgRzmZKjrZUwqFoadiRuNvd8CYzfG1PH9vfdj3ErPhx03YCgi2oLYu4fIY6FNO2/Cqqx1LubrlcPEi/+DFYXwogxp+w73NzUFaIab7ALqB1RvGwLpt97k3NMHmm7KCJbiCMA+LmFUkL1K3+rpZvmlklxR+C1LI=" Dec 30 17:56:25 volumio go-librespot[21484]: time="2025-12-30T17:56:25-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:25 volumio go-librespot[21484]: time="2025-12-30T17:56:25-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:25 volumio go-librespot[21484]: time="2025-12-30T17:56:25-06:00" level=debug msg="completed challenge" Dec 30 17:56:25 volumio go-librespot[21484]: time="2025-12-30T17:56: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 30 17:56:25 volumio ntpd[872]: IO: Listen normally on 784 eth0 169.254.82.16:123 Dec 30 17:56:25 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Dec 30 17:56:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:25 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.82.16 Dec 30 17:56:25 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.82.16 Dec 30 17:56:25 volumio avahi-daemon[664]: Withdrawing address record for 169.254.82.16 on eth0. Dec 30 17:56:25 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:25 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:25 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:25 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:25 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:26 volumio volumio[21223]: info: Applying required configuration parameters for plugin volusonic Dec 30 17:56:26 volumio volumio[21223]: info: Loading plugin "backup_restore"... Dec 30 17:56:26 volumio volumio[21437]: Starting albumart workers Dec 30 17:56:26 volumio volumio[21438]: Starting albumart workers Dec 30 17:56:26 volumio volumio[21223]: info: Applying required configuration parameters for plugin backup_restore Dec 30 17:56:26 volumio volumio[21223]: info: Plugin rpi_eeprom_config is not enabled Dec 30 17:56:26 volumio volumio[21223]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 17:56:26 volumio volumio[21223]: info: Loading plugin "scheduledrestart"... Dec 30 17:56:26 volumio volumio[21439]: Starting albumart workers Dec 30 17:56:27 volumio volumio[21223]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 17:56:27 volumio volumio[21223]: info: Plugin Bluetoothremote is not enabled Dec 30 17:56:27 volumio volumio[21223]: info: Plugin music_services_shield is not enabled Dec 30 17:56:27 volumio volumio[21223]: info: Loading plugin "Systeminfo"... Dec 30 17:56:27 volumio ntpd[872]: IO: Deleting interface #784 eth0, 169.254.82.16#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Dec 30 17:56:27 volumio volumio[21223]: info: Plugin peppymeterbasic is not enabled Dec 30 17:56:27 volumio volumio[21223]: info: Loading plugin "peppyspectrum"... Dec 30 17:56:28 volumio volumio[21223]: info: Loading i18n strings for locale en Dec 30 17:56:28 volumio volumio[21223]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 17:56:28 volumio volumio[21223]: Updating browse sources language Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::initPlayerControls Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: Express server listening on port 3000 Dec 30 17:56:28 volumio volumio[21223]: [Metrics] WebUI: 19s 89.06ms Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::resetVolumioState Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::getcurrentVolume Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:28 volumio sudo[21531]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 17:56:28 volumio sudo[21531]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:28 volumio sudo[21531]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:28 volumio sudo[21533]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 17:56:28 volumio sudo[21533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:28 volumio sudo[21533]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:28 volumio volumio[21223]: info: Volumio Network Manager: Network status updated: 1 Dec 30 17:56:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Dec 30 17:56:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:28 volumio volumio[21223]: info: VolumeController:: Volume=100 Mute =false Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::pushState Dec 30 17:56:28 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioPushState Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::updateTrackBlock Dec 30 17:56:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:28 volumio volumio[21223]: info: CorePlayQueue::getTrackBlock Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 17:56:28 volumio go-librespot[21537]: go-librespot daemon starting... Dec 30 17:56:28 volumio volumio-remote-updater[702]: [2025-12-30 17:56:28] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767138984 101 Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=debug msg="app state loaded" Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:28 volumio volumio[21223]: 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 30 17:56:28 volumio volumio[21223]: info: Reloading queue from file Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::setRepeat null single undefined Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::pushState Dec 30 17:56:28 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioPushState Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::setRandom null Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::pushState Dec 30 17:56:28 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioPushState Dec 30 17:56:28 volumio volumio[21223]: info: Setting Device type: Raspberry PI Dec 30 17:56:28 volumio volumio[21223]: info: VolumeController:: Volume=100 Mute =false Dec 30 17:56:28 volumio volumio[21223]: info: CoreStateMachine::pushState Dec 30 17:56:28 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioPushState Dec 30 17:56:28 volumio volumio[21223]: info: Completed loading Core Plugins Dec 30 17:56:28 volumio volumio[21223]: info: Preparing to generate the ALSA configuration file Dec 30 17:56:28 volumio sudo[21554]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 17:56:28 volumio sudo[21554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:28 volumio volumio[21223]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 17:56:28 volumio volumio[21223]: info: Discovery: Found device Volumio Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioGetState Dec 30 17:56:28 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:28 volumio volumio[21223]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 17:56:28 volumio volumio[21223]: info: Discovery: Found device Volumio Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioGetState Dec 30 17:56:28 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:28 volumio sudo[21554]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:28 volumio volumio[21223]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 17:56:28 volumio volumio[21223]: info: Reading ALSA contributions from plugins. Dec 30 17:56:28 volumio volumio[21223]: info: Upmpdcli Daemon Started Dec 30 17:56:28 volumio volumio[21223]: info: Asound.conf file unchanged, so no further update is needed Dec 30 17:56:28 volumio volumio[21223]: info: Output device has changed, restarting MPD Dec 30 17:56:28 volumio volumio[21223]: info: Output device has changed, restarting Shairport Sync Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-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 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-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 30 17:56:28 volumio sudo[21558]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 17:56:28 volumio sudo[21558]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=info msg="zeroconf server listening on port 33361" Dec 30 17:56:28 volumio sudo[21560]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 17:56:28 volumio volumio[21223]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:56:28 volumio sudo[21560]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:28 volumio sudo[21558]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:28 volumio volumio[21223]: info: ___________ START PLUGINS ___________ Dec 30 17:56:28 volumio volumio[21223]: info: ControllerMpd::onStart: Initializing MPD Dec 30 17:56:28 volumio volumio[21223]: info: Creating MPD Configuration file Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:28 volumio volumio[21223]: info: [1767138988873] CoreMusicLibrary::Adding element Media Servers Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:28 volumio sudo[21568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 17:56:28 volumio sudo[21568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:28 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 17:56:28 volumio sudo[21568]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:28 volumio sudo[21570]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 17:56:28 volumio sudo[21570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=debug msg="obtained new client token: AACiArHjlbYaVmP1GPXDSN4O7qKw+XPa8Pb7hnvPW/XNE7oAK7zReIqBMInCecPHDtTN+8m9q5F66wkC/2DEF3Vx9E6LPkJg16j9Narg4VzBbIn0AQeKGnPtCK4gvjjQuh0HuyU+0DLDF+R4mt2Vfp5xVP4es1V6GZ4eoRTLp5Yp3Rc/hskWtBqUjpI/OJFBAX1NJ1/xuzsLwC+yUYcGg1Ea0CtH/D7e8YLOjt+KFynpQ5Zr0+M23/HIfw==" Dec 30 17:56:28 volumio volumio[21223]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:28 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:28 volumio go-librespot[21539]: time="2025-12-30T17:56:28-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:29 volumio volumio[21223]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:56:29 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:29 volumio volumio[21223]: info: [1767138989013] CoreMusicLibrary::Adding element Last_100 Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:29 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 17:56:29 volumio systemd[1]: mpd.service: Consumed 5.891s CPU time. Dec 30 17:56:29 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:29 volumio volumio[21223]: info: [1767138989025] CoreMusicLibrary::Adding element Webradio Dec 30 17:56:29 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:29 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 17:56:29 volumio volumio[21223]: info: Initializing BBC Radios Dec 30 17:56:29 volumio go-librespot[21539]: time="2025-12-30T17:56:29-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:29 volumio go-librespot[21539]: time="2025-12-30T17:56:29-06:00" level=debug msg="completed challenge" Dec 30 17:56:29 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 17:56:29 volumio go-librespot[21539]: time="2025-12-30T17:56: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 30 17:56:29 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 17:56:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:29 volumio volumio[21223]: info: [1767138989194] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:29 volumio volumio[21223]: info: [1767138989218] CoreMusicLibrary::Adding element SoundCloud Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:29 volumio volumio[21223]: info: Creating Spotify config file Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:29 volumio sudo[21590]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 17:56:29 volumio sudo[21590]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 17:56:29 volumio sudo[21590]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:29 volumio volumio[21223]: info: [squeezelite_mc] Starting proxy server... Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:29 volumio volumio[21223]: info: [1767138989890] CoreMusicLibrary::Adding element YouTube2 Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source YouTube2 Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:29 volumio volumio[21223]: info: [1767138989921] CoreMusicLibrary::Adding element YouTube Music Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source YouTube2 Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source YouTube Music Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:29 volumio volumio[21223]: info: [1767138989940] CoreMusicLibrary::Adding element Podcast Dec 30 17:56:29 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source YouTube2 Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source YouTube Music Dec 30 17:56:29 volumio volumio[21223]: Cannot find translation for source Podcast Dec 30 17:56:29 volumio volumio[21223]: info: Loading i18n strings for locale en Dec 30 17:56:30 volumio volumio[21223]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 17:56:30 volumio volumio[21223]: Updating browse sources language Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source YouTube2 Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source YouTube Music Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source Podcast Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source YouTube2 Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source YouTube Music Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source Podcast Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:30 volumio volumio[21223]: info: [1767138990034] CoreMusicLibrary::Adding element Volusonic Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source YouTube2 Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source YouTube Music Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source Podcast Dec 30 17:56:30 volumio volumio[21223]: Cannot find translation for source Volusonic Dec 30 17:56:30 volumio volumio[21223]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 17:56:30 volumio volumio[21223]: info: Volumio Calling Home Dec 30 17:56:30 volumio volumio[21223]: info: [squeezelite_mc] Proxy server started on port 38279 Dec 30 17:56:30 volumio volumio[21223]: info: Preparing to generate the ALSA configuration file Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 17:56:30 volumio volumio[21223]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 17:56:30 volumio volumio[21223]: info: Reading ALSA contributions from plugins. Dec 30 17:56:30 volumio volumio[21223]: info: MPD Permissions set Dec 30 17:56:30 volumio volumio[21223]: info: MPD Permissions set Dec 30 17:56:30 volumio volumio[21223]: info: Volumio called home Dec 30 17:56:30 volumio volumio[21223]: info: Spotify config file written Dec 30 17:56:30 volumio sudo[21605]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 17:56:30 volumio sudo[21605]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:30 volumio volumio[21223]: 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 30 17:56:30 volumio volumio[21223]: info: VolumeController:: Volume=100 Mute =false Dec 30 17:56:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:30 volumio volumio[21223]: info: CoreStateMachine::pushState Dec 30 17:56:30 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::volumioPushState Dec 30 17:56:30 volumio volumio[21223]: info: [squeezelite_mc] Server discovery started Dec 30 17:56:30 volumio volumio[21223]: info: [squeezelite_mc] Player finder started Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:30 volumio go-librespot[21607]: go-librespot daemon starting... Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio sudo[21605]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:30 volumio volumio[21223]: info: No need to fix Spotify hosts Dec 30 17:56:30 volumio go-librespot[21615]: time="2025-12-30T17:56:30-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:30 volumio go-librespot[21615]: time="2025-12-30T17:56:30-06:00" level=debug msg="app state loaded" Dec 30 17:56:30 volumio go-librespot[21615]: time="2025-12-30T17:56:30-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:30 volumio go-librespot[21615]: time="2025-12-30T17:56:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:31 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.94.247 Dec 30 17:56:31 volumio avahi-daemon[664]: Registering new address record for 169.254.94.247 on eth0.IPv4. Dec 30 17:56:31 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:31 volumio volumio[21223]: 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 30 17:56:31 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:31 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:31 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:31 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.94.247 Dec 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-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 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-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 30 17:56:31 volumio volumio[21223]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 17:56:31 volumio volumio[21223]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 17:56:31 volumio volumio[21223]: 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 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-06:00" level=info msg="zeroconf server listening on port 42875" Dec 30 17:56:31 volumio volumio[21223]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 17:56:31 volumio volumio[21223]: SPOTIFY: BQCmxECMN6tOiCoBfmw5TbNF1Ozuo9weExR80H_k4zE_wqgO5uO_xD7sFzM-pqNG6-PEp6ZCzOv-iCCqtBWES0jBKXSkVnte4i5EBhu7fDytXzGtd6mAB9ltDK0iBchOFajm8BOus63eknUalZfGRFSk47PlUqzFQXdeUvCZH4kQ7bovX-vx5qwRyvjAwFoM36heXOCcLTSURPaY06OARqn-FS7UF1kI9LNqMDE Dec 30 17:56:31 volumio volumio[21223]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 17:56:31 volumio volumio[21223]: info: New Spotify access token = BQCmxECMN6tOiCoBfmw5TbNF1Ozuo9weExR80H_k4zE_wqgO5uO_xD7sFzM-pqNG6-PEp6ZCzOv-iCCqtBWES0jBKXSkVnte4i5EBhu7fDytXzGtd6mAB9ltDK0iBchOFajm8BOus63eknUalZfGRFSk47PlUqzFQXdeUvCZH4kQ7bovX-vx5qwRyvjAwFoM36heXOCcLTSURPaY06OARqn-FS7UF1kI9LNqMDE Dec 30 17:56:31 volumio volumio[21223]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 17:56:31 volumio sudo[21646]: 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 30 17:56:31 volumio sudo[21646]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:31 volumio volumio[21223]: info: Starting Shairport Sync Dec 30 17:56:31 volumio sudo[21646]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:31 volumio volumio[21223]: info: Starting Shairport Sync Dec 30 17:56:31 volumio volumio[21223]: info: Starting Shairport Sync Dec 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-06:00" level=debug msg="obtained new client token: AACFuXJcijpy7DDkkAKMoNtH9rgnEmYHXP4Cof8BfoOuOkJ/pgiFCoo3bP3uWdRHmIZWK8qbXXN6Mr2jRX/LDpTVwXqQskTjQcT074pAJliod9d9Tpfif/8FVffgWlxwtyp9vzAqX2GL4x9lxCdtuJr4ImurAr4IyYXlYCKL47kytU+aQ3JJlgirUyIArepyAQWb9ltnBFc5vAwRnUoTDxaMm1op/PIFIoBv/cfJueH5OoZNnZ+GqjRFKA==" Dec 30 17:56:31 volumio sudo[21649]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:56:31 volumio sudo[21649]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:31 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.94.247 Dec 30 17:56:31 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.94.247 Dec 30 17:56:31 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:31 volumio avahi-daemon[664]: Withdrawing address record for 169.254.94.247 on eth0. Dec 30 17:56:31 volumio sudo[21651]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:31 volumio sudo[21651]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:31 volumio sudo[21653]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:56:31 volumio sudo[21653]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-06:00" level=debug msg="completed challenge" Dec 30 17:56:31 volumio go-librespot[21615]: time="2025-12-30T17:56:31-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:31 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:32 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:32 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:32 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:32 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 17:56:32 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 17:56:32 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:56:32 volumio systemd[1]: shairport-sync.service: Consumed 2.077s CPU time. Dec 30 17:56:32 volumio volumio[21223]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 17:56:32 volumio volumio[21223]: info: Asound.conf file unchanged, so no further update is needed Dec 30 17:56:32 volumio volumio[21223]: info: Output device has changed, restarting MPD Dec 30 17:56:32 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:56:32 volumio sudo[21649]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:32 volumio volumio[21223]: info: Output device has changed, restarting Shairport Sync Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:32 volumio sudo[21653]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:32 volumio sudo[21651]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:32 volumio sudo[21691]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 17:56:32 volumio sudo[21691]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:32 volumio volumio[21223]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:56:32 volumio sudo[21696]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 17:56:32 volumio sudo[21694]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 17:56:32 volumio sudo[21694]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:32 volumio sudo[21696]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:32 volumio sudo[21694]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:32 volumio sudo[21691]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:32 volumio volumio[21223]: info: PeppySpectrum ---peppyspectrum status stop Dec 30 17:56:32 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 17:56:32 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 17:56:32 volumio systemd[1]: mpd.service: Consumed 2.993s CPU time. Dec 30 17:56:32 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 17:56:32 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 17:56:32 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 17:56:32 volumio sudo[21722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppyspectrum.service Dec 30 17:56:32 volumio sudo[21722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:32 volumio volumio[21223]: info: MPD Permissions set Dec 30 17:56:32 volumio volumio[21223]: 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 30 17:56:32 volumio volumio[21223]: info: Shairport-Sync Started Dec 30 17:56:32 volumio volumio[21223]: Error adding Membership: Error: addMembership EINVAL Dec 30 17:56:32 volumio volumio[21223]: info: Shairport-Sync Started Dec 30 17:56:32 volumio volumio[21223]: info: Shairport-Sync Started Dec 30 17:56:32 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 17:56:32 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 17:56:32 volumio sudo[21727]: 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 30 17:56:32 volumio sudo[21727]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:32 volumio sudo[21727]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:32 volumio sudo[21722]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:32 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio sudo[21731]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 17:56:32 volumio sudo[21731]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:32 volumio volumio[21223]: info: peppyspectrum Daemon Stop Dec 30 17:56:32 volumio systemd[1]: Reloading. Dec 30 17:56:32 volumio volumio[21223]: info: CoreCommandRouter::volumioGetState Dec 30 17:56:32 volumio volumio[21223]: info: CorePlayQueue::getTrack 0 Dec 30 17:56:33 volumio sudo[21728]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 17:56:33 volumio sudo[21728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 17:56:33 volumio sudo[21728]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:33 volumio volumio[21223]: info: Starting Shairport Sync Dec 30 17:56:33 volumio volumio[21223]: 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 30 17:56:33 volumio volumio[21223]: info: Spotify Successfully logged in Dec 30 17:56:33 volumio sudo[21740]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:56:33 volumio volumio[21223]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:56:33 volumio volumio[21223]: info: [1767138993437] CoreMusicLibrary::Adding element Spotify Dec 30 17:56:33 volumio sudo[21740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:33 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:56:33 volumio volumio[21223]: Cannot find translation for source Bandcamp Discover Dec 30 17:56:33 volumio volumio[21223]: Cannot find translation for source SoundCloud Dec 30 17:56:33 volumio volumio[21223]: Cannot find translation for source YouTube2 Dec 30 17:56:33 volumio volumio[21223]: Cannot find translation for source YouTube Music Dec 30 17:56:33 volumio volumio[21223]: Cannot find translation for source Podcast Dec 30 17:56:33 volumio volumio[21223]: Cannot find translation for source Volusonic Dec 30 17:56:33 volumio volumio[21223]: Cannot find translation for source Spotify Dec 30 17:56:33 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:33 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:33 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:56:33 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:56:34 volumio volumio[21223]: info: go-librespot daemon successfully initialized Dec 30 17:56: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 30 17:56: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 30 17:56:36 volumio sudo[21731]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:36 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:36 volumio sudo[21761]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Dec 30 17:56:36 volumio sudo[21761]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:36 volumio sudo[21761]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:36 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 30 17:56:36 volumio sudo[21765]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 30 17:56:36 volumio sudo[21765]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:36 volumio go-librespot[21763]: go-librespot daemon starting... Dec 30 17:56:36 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 17:56:36 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 17:56:36 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:56:36 volumio systemd[1]: shairport-sync.service: Consumed 1.489s CPU time. Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=debug msg="app state loaded" Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:36 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:56:36 volumio sudo[21740]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:36 volumio volumio[21223]: info: Shairport-Sync Started Dec 30 17:56:36 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 17:56:36 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 30 17:56:36 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 17:56:36 volumio sudo[21765]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56: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-gew4.spotify.com:80]" Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-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 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-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 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=info msg="zeroconf server listening on port 38045" Dec 30 17:56:36 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.118.133 Dec 30 17:56:36 volumio avahi-daemon[664]: Registering new address record for 169.254.118.133 on eth0.IPv4. Dec 30 17:56:36 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:36 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=debug msg="obtained new client token: AABMqDE6hHj+owAlpSoJE51/duI/omCjiXzAP/bPLR0i+eXumMiLQCrDrqJOZYGpFfZC4A1oH7+WQIRI1kYzZSKuFH/VGeG34XBdXZDNgkR7ZQrwnKp3aKqxcuVUstLStSSuJZcbZmBudh2WNWZLENWA1us1Gx1lyS5hpQ9+9wRl+GSGdgslmza9oq4mh/lCU6ZFVIn9tpKCqBdq2biU/ylqR0cnEUBAqt3BYu5wd8NE8puFMuXN5AFVZQ==" Dec 30 17:56:36 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:36 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56:36-06:00" level=debug msg="completed challenge" Dec 30 17:56:36 volumio go-librespot[21767]: time="2025-12-30T17:56: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 30 17:56:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:37 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:37 volumio sudo[21806]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:37 volumio sudo[21806]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:37 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.118.133 Dec 30 17:56:37 volumio sudo[21806]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:37 volumio volumio[21223]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 30 17:56:37 volumio sudo[21810]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 30 17:56:37 volumio sudo[21810]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:37 volumio sudo[21810]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:37 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 30 17:56:37 volumio sudo[21813]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 30 17:56:37 volumio sudo[21813]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:37 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 30 17:56:37 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 30 17:56:37 volumio sudo[21813]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:37 volumio volumio[21223]: info: Initializing connection to go-librespot Websocket Dec 30 17:56:37 volumio volumio[21223]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 17:56:37 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.118.133 Dec 30 17:56:37 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.118.133 Dec 30 17:56:37 volumio avahi-daemon[664]: Withdrawing address record for 169.254.118.133 on eth0. Dec 30 17:56:37 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:37 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:37 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:37 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:37 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:38 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:38 volumio sudo[21836]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:38 volumio sudo[21836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:38 volumio sudo[21836]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:38 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:38 volumio sudo[21839]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:38 volumio sudo[21839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:38 volumio sudo[21839]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:39 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 17:56:39 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:39 volumio sudo[21843]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:39 volumio sudo[21843]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:39 volumio mpd[21759]: 2025-12-30T17:56:39 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 30 17:56:39 volumio sudo[21843]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:39 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 30 17:56:39 volumio sudo[21560]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:39 volumio sudo[21570]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:39 volumio sudo[21696]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:39 volumio volumio[21223]: error: MPD error: The expression evaluated to a falsy value: Dec 30 17:56:39 volumio volumio[21223]: assert.ok(self.idling) Dec 30 17:56:39 volumio volumio[21223]: error: The expression evaluated to a falsy value: Dec 30 17:56:39 volumio volumio[21223]: assert.ok(self.idling) Dec 30 17:56:39 volumio volumio[21223]: error: MPD error: The expression evaluated to a falsy value: Dec 30 17:56:39 volumio volumio[21223]: assert.ok(self.idling) Dec 30 17:56:39 volumio volumio[21223]: error: The expression evaluated to a falsy value: Dec 30 17:56:39 volumio volumio[21223]: assert.ok(self.idling) Dec 30 17:56:39 volumio volumio[21223]: error: updateQueue error: null Dec 30 17:56:39 volumio volumio[21223]: info: MPD running with PID21759 Dec 30 17:56:39 volumio volumio[21223]: ,establishing connection Dec 30 17:56:39 volumio volumio[21223]: error: updateQueue error: null Dec 30 17:56:39 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:39 volumio sudo[21850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:39 volumio sudo[21850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:39 volumio sudo[21850]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Dec 30 17:56:39 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:39 volumio go-librespot[21852]: go-librespot daemon starting... Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=debug msg="app state loaded" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-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 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-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 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=info msg="zeroconf server listening on port 34745" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=debug msg="obtained new client token: AABVrkmArxw7wgtCz+DqyQdpXQ+/pXqLXO673eWdFpNKtAWdahzxUIweaaVLiRNAp6TrLblMdPVxQ2YvMydsHqIJcEeaGVYtYSlIBGTICJZkcrTW2B7wf6fTzbKbvCQ49Y3KAfeKj4IZAuw7/vFC74UaLPHmNnpq57NcMnfbrUgHNwSwgQTO4kWKnneinqOnHNbxLy8x4AS1U16BdwlXoIOLE3uR49Ukd9e6Z6hv4ARSus/IrLjza/daMw==" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:40 volumio volumio[21223]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:56:40 volumio sudo[21861]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:56:40 volumio sudo[21861]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56:40-06:00" level=debug msg="completed challenge" Dec 30 17:56:40 volumio sudo[21861]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:40 volumio go-librespot[21853]: time="2025-12-30T17:56: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 30 17:56:40 volumio volumio[21223]: info: Completed starting Core Plugins Dec 30 17:56:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:40 volumio volumio[21223]: info: ------------------------------------------- Dec 30 17:56:40 volumio volumio[21223]: info: ----- MyVolumio plugins startup ---- Dec 30 17:56:40 volumio volumio[21223]: info: ------------------------------------------- Dec 30 17:56:40 volumio volumio[21223]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 30 17:56:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:40 volumio volumio[21223]: info: Initializing connection to go-librespot Websocket Dec 30 17:56:40 volumio volumio[21223]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 17:56:42 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.90.80 Dec 30 17:56:42 volumio avahi-daemon[664]: Registering new address record for 169.254.90.80 on eth0.IPv4. Dec 30 17:56:42 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:42 volumio sudo[21881]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 17:56:42 volumio sudo[21881]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:42 volumio sudo[21885]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 17:56:42 volumio sudo[21885]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:42 volumio sudo[21899]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 30 17:56:42 volumio sudo[21899]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:42 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:42 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:42 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:42 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 30 17:56:42 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 30 17:56:42 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 30 17:56:42 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 30 17:56:42 volumio sudo[21881]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:42 volumio sudo[21885]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:42 volumio sudo[21899]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:42 volumio mpd_monitor.sh[21905]: MPD Monitor Service: Starting MPD Monitor Service Dec 30 17:56:42 volumio volumio[21223]: info: Successfully started MPD Monitor Dec 30 17:56:42 volumio volumio[21223]: info: Successfully started MPD Monitor Dec 30 17:56:42 volumio volumio[21223]: info: Successfully started MPD Monitor Dec 30 17:56:43 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.90.80 Dec 30 17:56:43 volumio volumio[21223]: info: Initializing connection to go-librespot Websocket Dec 30 17:56:43 volumio volumio[21223]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 17:56:43 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.90.80 Dec 30 17:56:43 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.90.80 Dec 30 17:56:43 volumio avahi-daemon[664]: Withdrawing address record for 169.254.90.80 on eth0. Dec 30 17:56:43 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:43 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Dec 30 17:56:43 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:43 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:43 volumio go-librespot[21925]: go-librespot daemon starting... Dec 30 17:56:43 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:43 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:43 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-06:00" level=debug msg="app state loaded" Dec 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-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 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-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 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-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 30 17:56:43 volumio go-librespot[21926]: time="2025-12-30T17:56:43-06:00" level=info msg="zeroconf server listening on port 44533" Dec 30 17:56:44 volumio go-librespot[21926]: time="2025-12-30T17:56:44-06:00" level=debug msg="obtained new client token: AAAQ+yUzmkL8QeZECAvpIHoZbvLBs5R61agh6yKMLLb7tM6i41IRdwu1eL9Z1TfZYYHQvUID1Yc8Qmpp6pdQ5IAGMPPswKrsjbYIZn0FxQz6nzKHyjt8qX3XMW5IMyUYjhkuRDsb1ZGofhLOiM76A6cbwzh+QOervYvYDSY5owi8n3af/mGrrjmAqWywa8vxkpJ9z5bV7ZFj+trU4w9QgHM24tnfi79pB2YooF0t6yHZr3ARlfll82g=" Dec 30 17:56:44 volumio go-librespot[21926]: time="2025-12-30T17:56:44-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:44 volumio go-librespot[21926]: time="2025-12-30T17:56:44-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:44 volumio go-librespot[21926]: time="2025-12-30T17:56:44-06:00" level=debug msg="completed challenge" Dec 30 17:56:44 volumio go-librespot[21926]: time="2025-12-30T17:56: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 30 17:56:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:45 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 17:56:46 volumio volumio[21223]: info: Initializing connection to go-librespot Websocket Dec 30 17:56:47 volumio volumio[21223]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 17:56:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Dec 30 17:56:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:47 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:47 volumio go-librespot[21935]: go-librespot daemon starting... Dec 30 17:56:47 volumio go-librespot[21936]: time="2025-12-30T17:56:47-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:47 volumio go-librespot[21936]: time="2025-12-30T17:56:47-06:00" level=debug msg="app state loaded" Dec 30 17:56:47 volumio go-librespot[21936]: time="2025-12-30T17:56:47-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:47 volumio go-librespot[21936]: time="2025-12-30T17:56:47-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-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 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-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 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-06:00" level=info msg="zeroconf server listening on port 33323" Dec 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-06:00" level=debug msg="obtained new client token: AADroEHU5FiRKPkmBNY2tmcIrzypW9kDOdDFYTlheQcLMNByAtpahyxGAyQrfckDVZNwBPg3W4/VunUkB3IL5UVmitZhcHfmJSHQDn1rGyUmhOuwG33zLOC7U01BXd5ok5UNDlbmIQiU1zYpABWzW1+IJ0oZXDMEnKwPC+7E/bXurLjTPXK1PB1Bw2ZEp7uZ4l/0CHm2Q5ghlLPm31TC6eihlQeDrGisULGmM8mReXoAa7SwZFSwRj0=" Dec 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-06:00" level=debug msg="completed challenge" Dec 30 17:56:48 volumio go-librespot[21936]: time="2025-12-30T17:56:48-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:48 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.18.85 Dec 30 17:56:48 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:48 volumio avahi-daemon[664]: Registering new address record for 169.254.18.85 on eth0.IPv4. Dec 30 17:56:48 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:48 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:48 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:49 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.18.85 Dec 30 17:56:49 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.18.85 Dec 30 17:56:49 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.18.85 Dec 30 17:56:49 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:49 volumio avahi-daemon[664]: Withdrawing address record for 169.254.18.85 on eth0. Dec 30 17:56:49 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:49 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:49 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:49 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 30 17:56:49 volumio volumio[21223]: info: Adding plugin bluetooth to MyMusic Plugins Dec 30 17:56:49 volumio volumio[21223]: info: Adding plugin multiroom to MyMusic Plugins Dec 30 17:56:49 volumio volumio[21223]: info: Adding plugin metavolumio to MyMusic Plugins Dec 30 17:56:49 volumio volumio[21223]: info: Adding plugin cd_controller to MyMusic Plugins Dec 30 17:56:49 volumio volumio[21223]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 30 17:56:49 volumio volumio[21223]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 30 17:56:49 volumio volumio[21223]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 30 17:56:49 volumio volumio[21223]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 30 17:56:50 volumio volumio[21223]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 30 17:56:50 volumio volumio[21223]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 30 17:56:50 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:50 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:50 volumio volumio[21223]: info: Starting MyVolumio Remote Streaming Endpoints Dec 30 17:56:50 volumio volumio[21223]: info: MyVolumio login type: Token Dec 30 17:56:50 volumio volumio[21223]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 30 17:56:50 volumio volumio[21223]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 30 17:56:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Dec 30 17:56:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:51 volumio volumio[21223]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 30 17:56:51 volumio volumio[21223]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 30 17:56:51 volumio volumio[21223]: info: Streaming services startup Dec 30 17:56:51 volumio volumio[21223]: info: Starting Streaming Daemon Dec 30 17:56:51 volumio sudo[21979]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 17:56:51 volumio sudo[21979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:51 volumio volumio[21223]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 30 17:56:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:51 volumio go-librespot[21977]: go-librespot daemon starting... Dec 30 17:56:51 volumio sudo[21979]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=debug msg="app state loaded" Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:51 volumio volumio[21223]: info: Initializing connection to go-librespot Websocket Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:51 volumio volumio[21223]: error: Cannot start Volumio Streaming Daemon Dec 30 17:56:51 volumio volumio[21223]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 30 17:56:51 volumio volumio[21223]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=debug msg="new websocket client" Dec 30 17:56:51 volumio volumio[21223]: info: Connection to go-librespot Websocket established Dec 30 17:56:51 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56: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 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56: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 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56: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 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=info msg="zeroconf server listening on port 42295" Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=debug msg="obtained new client token: AADQbZT4qCaPPEqSngDPjwwo/MJpYQYHrO1j+/ooLIFfGfeT4/Rl+Ir2ZQ4R4ozM3EsJu/GQa1QQET+zFz0S/7nFLqJjx1R0HyXodemcZNz4dJbVBWpzGqyKzfy3D/oxQFYMYqXfE2DjCIm2SkcABgXQFQTWlQ9x7ir0s/4ocOmkagQXoWWWVlAdyeDXDNqndBHB4Hhq9fLIZRI+UDpvsdkaY/a4KhHi9Ai4/qXOIv1kP8QcHBHOsqgAnA==" Dec 30 17:56:51 volumio volumio[21223]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 30 17:56:51 volumio go-librespot[21985]: time="2025-12-30T17:56:51-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:52 volumio go-librespot[21985]: time="2025-12-30T17:56:52-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:52 volumio go-librespot[21985]: time="2025-12-30T17:56:52-06:00" level=debug msg="completed challenge" Dec 30 17:56:52 volumio go-librespot[21985]: time="2025-12-30T17:56:52-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:56:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:52 volumio volumio[21223]: info: Connection to go-librespot Websocket closed Dec 30 17:56:52 volumio volumio[21223]: info: MyVolumio token set successfully Dec 30 17:56:52 volumio volumio[21223]: info: MYVOLUMIO: Adding device Dec 30 17:56:52 volumio volumio[21223]: info: MYVOLUMIO: Evaluating Server Dec 30 17:56:52 volumio volumio[21223]: info: MyVolumio status changed Dec 30 17:56:52 volumio volumio[21223]: info: Streaming services startup Dec 30 17:56:52 volumio volumio[21223]: info: Starting Streaming Daemon Dec 30 17:56:52 volumio volumio[21223]: info: Removing browser output: myVolumio user plan is not superstar Dec 30 17:56:52 volumio volumio[21223]: info: Removing audio output: Dec 30 17:56:52 volumio volumio[21223]: info: Stoppping Tunnel 1 Dec 30 17:56:52 volumio sudo[22029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 30 17:56:52 volumio sudo[22029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:52 volumio sudo[22031]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 30 17:56:52 volumio sudo[22031]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:52 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 30 17:56:52 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 30 17:56:52 volumio sudo[22029]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:52 volumio volumio[21223]: error: Cannot start Volumio Streaming Daemon Dec 30 17:56:52 volumio volumio[21223]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 30 17:56:52 volumio volumio[21223]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 30 17:56:52 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 30 17:56:52 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 30 17:56:52 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 30 17:56:52 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 30 17:56:52 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 30 17:56:52 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 30 17:56:52 volumio sudo[22031]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:52 volumio volumio[21223]: info: Remote SSH Stopped Dec 30 17:56:52 volumio volumio[21223]: info: Setting Geolocation for MyVolumio to us1 Dec 30 17:56:52 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:52 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:52 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:52 volumio volumio[21223]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Dec 30 17:56:53 volumio volumio[21223]: info: Updating MyVolumio device info Dec 30 17:56:53 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:53 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:53 volumio volumio[21223]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:56:54 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.111.192 Dec 30 17:56:54 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:54 volumio avahi-daemon[664]: Registering new address record for 169.254.111.192 on eth0.IPv4. Dec 30 17:56:54 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:54 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:54 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:54 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.111.192 Dec 30 17:56:54 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.111.192 Dec 30 17:56:54 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.111.192 Dec 30 17:56:54 volumio avahi-daemon[664]: Withdrawing address record for 169.254.111.192 on eth0. Dec 30 17:56:54 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:54 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:54 volumio volumio[21223]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Dec 30 17:56:54 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:54 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:54 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:54 volumio volumio[21223]: info: Getting Spotify volume Dec 30 17:56:54 volumio volumio[21223]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 17:56:54 volumio volumio[21223]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 30 17:56:54 volumio volumio[21223]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 30 17:56:54 volumio volumio[21223]: errno: -111, Dec 30 17:56:54 volumio volumio[21223]: code: 'ECONNREFUSED', Dec 30 17:56:54 volumio volumio[21223]: syscall: 'connect', Dec 30 17:56:54 volumio volumio[21223]: address: '127.0.0.1', Dec 30 17:56:54 volumio volumio[21223]: port: 9879, Dec 30 17:56:54 volumio volumio[21223]: response: undefined Dec 30 17:56:54 volumio volumio[21223]: } Dec 30 17:56:54 volumio volumio[21223]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 17:56:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Dec 30 17:56:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:55 volumio go-librespot[22078]: go-librespot daemon starting... Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="app state loaded" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:55 volumio sudo[22087]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 17:55' Dec 30 17:56:55 volumio sudo[22087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=info msg="zeroconf server listening on port 41085" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="obtained new client token: AACNFg5n2Pb6s9k+djw4e9x5ai3ItewoWLPVB1STb780puxmG6kQMLtIDts2DuAW8ug+n42wQ4SZeyxlKVmsGLFGs2eAQ6FGgUDyqnT/IUigvc93YqvhrM0KPKeN3vRPmDY/LzjOFr0ewAm0WSyEfh4QCQXXnsFXqyI+hLbN5EtmrByJc7L0DEr75FSR/FNgTyesoHY/6iqphzf9LX2x/+dcymTsv8e5BWocszUvu/08O8t3NQPNRYxATg==" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-06:00" level=debug msg="completed challenge" Dec 30 17:56:55 volumio sudo[22087]: pam_unix(sudo:session): session closed for user root Dec 30 17:56:55 volumio go-librespot[22079]: time="2025-12-30T17:56:55-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 30 17:56:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:55 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:55 volumio volumio-remote-updater[702]: [2025-12-30 17:56:55] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 30 17:56:55 volumio volumio-remote-updater[702]: [2025-12-30 17:56:55] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 30 17:56:55 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 30 17:56:55 volumio systemd[1]: volumio.service: Consumed 59.319s CPU time. Dec 30 17:56:55 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 17:56:55 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 17:56:56 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1142. Dec 30 17:56:56 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 30 17:56:56 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 30 17:56:56 volumio systemd[1]: volumio.service: Consumed 59.319s CPU time. Dec 30 17:56:56 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 30 17:56:56 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 30 17:56:58 volumio volumio[22103]: info: ------------------------------------------- Dec 30 17:56:58 volumio volumio[22103]: info: ----- Volumio3 ---- Dec 30 17:56:58 volumio volumio[22103]: info: ------------------------------------------- Dec 30 17:56:58 volumio volumio[22103]: info: ----- System startup ---- Dec 30 17:56:58 volumio volumio[22103]: info: ------------------------------------------- Dec 30 17:56:58 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.56.32 Dec 30 17:56:58 volumio avahi-daemon[664]: Registering new address record for 169.254.56.32 on eth0.IPv4. Dec 30 17:56:58 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:56:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Dec 30 17:56:58 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:58 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:58 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:58 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:58 volumio volumio[22103]: info: MYVOLUMIO Environment detected Dec 30 17:56:58 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:56:58 volumio go-librespot[22140]: go-librespot daemon starting... Dec 30 17:56:58 volumio go-librespot[22144]: time="2025-12-30T17:56:58-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:56:58 volumio go-librespot[22144]: time="2025-12-30T17:56:58-06:00" level=debug msg="app state loaded" Dec 30 17:56:58 volumio go-librespot[22144]: time="2025-12-30T17:56:58-06:00" level=debug msg="stored credentials not found" Dec 30 17:56:58 volumio go-librespot[22144]: time="2025-12-30T17:56:58-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:56:59 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.56.32 Dec 30 17:56:59 volumio volumio[22103]: info: Plugin folders cleanup Dec 30 17:56:59 volumio volumio[22103]: info: Scanning into folder /volumio/app/plugins/ Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category audio_interface Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category miscellanea Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category music_service Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category plugins.json Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category system_controller Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category user_interface Dec 30 17:56:59 volumio volumio[22103]: info: Scanning into folder /data/plugins/ Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category audio_interface Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category music_service Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category system_controller Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category system_hardware Dec 30 17:56:59 volumio volumio[22103]: info: Scanning category user_interface Dec 30 17:56:59 volumio volumio[22103]: info: Plugin folders cleanup completed Dec 30 17:56:59 volumio volumio[22103]: info: ------------------------------------------- Dec 30 17:56:59 volumio volumio[22103]: info: ----- Core plugins startup ---- Dec 30 17:56:59 volumio volumio[22103]: info: ------------------------------------------- Dec 30 17:56:59 volumio volumio[22103]: info: Loading plugins from folder /volumio/app/plugins/ Dec 30 17:56:59 volumio volumio[22103]: info: Adding plugin upnp to MyMusic Plugins Dec 30 17:56:59 volumio volumio[22103]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 30 17:56:59 volumio volumio[22103]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 30 17:56:59 volumio volumio[22103]: info: Loading plugins from folder /data/plugins/ Dec 30 17:56:59 volumio volumio[22103]: info: Loading plugin "system"... Dec 30 17:56:59 volumio volumio[22103]: info: Loading plugin "appearance"... Dec 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-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 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-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 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-06:00" level=info msg="zeroconf server listening on port 37975" Dec 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-06:00" level=debug msg="obtained new client token: AABSfvo/hE6uEnhUVqf33Znhykc+n9iLo9o6L4uV8+yNPmD0wma5fH+yAy/hylTYRW6H/fCtZE0HzUoz8zR8XXUp5+wxYg7qAD1KSN4uqR6n2113ibZKMymtyrTi+/8Bo5b8jH3p9BFq929//PKqdMz4jBE6brTyErdTjUyHTXv94ZLgmVosvrn9mbUhsC6dEHRmRGHOr1sB4IqFzp+BIrGa958akn0gCEcQFWO+DeRppZV1jFFmOyliDw==" Dec 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-06:00" level=debug msg="completed keyexchange" Dec 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56:59-06:00" level=debug msg="completed challenge" Dec 30 17:56:59 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.56.32 Dec 30 17:56:59 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.56.32 Dec 30 17:56:59 volumio avahi-daemon[664]: Withdrawing address record for 169.254.56.32 on eth0. Dec 30 17:56:59 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:56:59 volumio go-librespot[22144]: time="2025-12-30T17:56: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 30 17:56:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:56:59 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:56:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:56:59 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:56:59 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:56:59 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "network"... Dec 30 17:57:00 volumio volumio[22103]: info: Refreshing Cached IP Addresses Dec 30 17:57:00 volumio sudo[22171]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 17:57:00 volumio sudo[22171]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:00 volumio sudo[22173]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 17:57:00 volumio sudo[22173]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:00 volumio sudo[22171]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "services"... Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "alsa_controller"... Dec 30 17:57:00 volumio sudo[22173]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:00 volumio sudo[22180]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 30 17:57:00 volumio sudo[22180]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:00 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "wizard"... Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "networkfs"... Dec 30 17:57:00 volumio volumio[22103]: info: Starting Udev Watcher for removable devices Dec 30 17:57:00 volumio volumio[22103]: info: Ignoring mount for partition: boot Dec 30 17:57:00 volumio volumio[22103]: info: Ignoring mount for partition: volumio Dec 30 17:57:00 volumio volumio[22103]: info: Ignoring mount for partition: volumio_data Dec 30 17:57:00 volumio volumio[22103]: info: Mounting Device Wikipedia Dec 30 17:57:00 volumio sudo[22210]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 30 17:57:00 volumio sudo[22210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:00 volumio sudo[22210]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:00 volumio volumio[22103]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 17:57:00 volumio volumio[22103]: dmesg(1) may have more information after failed mount system call. Dec 30 17:57:00 volumio volumio[22103]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 30 17:57:00 volumio volumio[22103]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 30 17:57:00 volumio volumio[22103]: dmesg(1) may have more information after failed mount system call. Dec 30 17:57:00 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "volumio_command_line_client"... Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "upnp"... Dec 30 17:57:00 volumio volumio[22103]: info: [1767139020716] Starting Upmpd Daemon Dec 30 17:57:00 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "my_music"... Dec 30 17:57:00 volumio volumio[22103]: info: Loading plugin "mpd"... Dec 30 17:57:00 volumio volumio-remote-updater[702]: [2025-12-30 17:57:00] [connect] Successful connection Dec 30 17:57:00 volumio sudo[22180]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:01 volumio volumio[22103]: info: Loading plugin "upnp_browser"... Dec 30 17:57:02 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 17:57:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Dec 30 17:57:02 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:02 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:02 volumio go-librespot[22213]: go-librespot daemon starting... Dec 30 17:57:02 volumio go-librespot[22216]: time="2025-12-30T17:57:02-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:57:02 volumio go-librespot[22216]: time="2025-12-30T17:57:02-06:00" level=debug msg="app state loaded" Dec 30 17:57:02 volumio go-librespot[22216]: time="2025-12-30T17:57:02-06:00" level=debug msg="stored credentials not found" Dec 30 17:57:02 volumio go-librespot[22216]: time="2025-12-30T17:57:02-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=info msg="zeroconf server listening on port 41429" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=debug msg="obtained new client token: AADo2Bbn2IMzJ3FfOd/dc0rwAAgsARCQMb0tdsWMm7nh1+BWMNCcySpogV0ZxUJbynleSGWMFrxbUeNULHuDiqWoC/6N/wOZf3Cdxuc/bZ+Y44sxAjO1wHT/ICvvz4C3Z+L0BB81NfJaxXN94q9oBONkfc96oOJb3uE5W/cgQPs7Z/ACre3V8kVpChS7EmGriS0VBBFV0CLwhmHTpaqwkRWNoSfX5n0aq/onoztxGaCUciM1sE3OnE5rgQ==" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=debug msg="completed keyexchange" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=debug msg="completed challenge" Dec 30 17:57:03 volumio go-librespot[22216]: time="2025-12-30T17:57:03-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:57:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:57:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:57:04 volumio volumio[22103]: info: Loading plugin "alarm-clock"... Dec 30 17:57:04 volumio volumio[22103]: info: Loading plugin "airplay_emulation"... Dec 30 17:57:04 volumio volumio[22103]: info: Starting Shairport Sync Dec 30 17:57:04 volumio volumio[22103]: info: Loading plugin "last_100"... Dec 30 17:57:04 volumio volumio[22103]: info: Loading plugin "webradio"... Dec 30 17:57:04 volumio volumio[22103]: info: Loading plugin "i2s_dacs"... Dec 30 17:57:04 volumio volumio[22103]: info: I2S DAC not set, start Auto-detection Dec 30 17:57:04 volumio volumio[22103]: info: Loading plugin "volumiodiscovery"... Dec 30 17:57:04 volumio volumio[22103]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 17:57:04 volumio volumio[22103]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:57:04 volumio volumio[22103]: *** WARNING *** For more information see Dec 30 17:57:04 volumio volumio[22103]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 17:57:04 volumio volumio[22103]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:57:04 volumio volumio[22103]: *** WARNING *** For more information see Dec 30 17:57:04 volumio node[22103]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 30 17:57:04 volumio node[22103]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:57:04 volumio node[22103]: *** WARNING *** For more information see Dec 30 17:57:04 volumio node[22103]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 30 17:57:04 volumio node[22103]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 30 17:57:04 volumio node[22103]: *** WARNING *** For more information see Dec 30 17:57:04 volumio volumio[22103]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 30 17:57:04 volumio volumio[22103]: info: Discovery: Started advertising with name: Volumio Dec 30 17:57:04 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 30 17:57:04 volumio volumio[22103]: info: Loading plugin "bandcamp"... Dec 30 17:57:04 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.72.117 Dec 30 17:57:04 volumio avahi-daemon[664]: Registering new address record for 169.254.72.117 on eth0.IPv4. Dec 30 17:57:04 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:57:04 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:04 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:04 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:05 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.117 Dec 30 17:57:05 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.72.117 Dec 30 17:57:05 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.72.117 Dec 30 17:57:05 volumio avahi-daemon[664]: Withdrawing address record for 169.254.72.117 on eth0. Dec 30 17:57:05 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:57:05 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:05 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:57:05 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:05 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:05 volumio volumio[22103]: info: Plugin calmradio is not enabled Dec 30 17:57:05 volumio volumio[22103]: info: Loading plugin "soundcloud"... Dec 30 17:57:06 volumio volumio[22103]: info: Loading plugin "spop"... Dec 30 17:57:06 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 17:57:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Dec 30 17:57:06 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:06 volumio go-librespot[22259]: go-librespot daemon starting... Dec 30 17:57:06 volumio go-librespot[22260]: time="2025-12-30T17:57:06-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:57:06 volumio go-librespot[22260]: time="2025-12-30T17:57:06-06:00" level=debug msg="app state loaded" Dec 30 17:57:06 volumio go-librespot[22260]: time="2025-12-30T17:57:06-06:00" level=debug msg="stored credentials not found" Dec 30 17:57:06 volumio go-librespot[22260]: time="2025-12-30T17:57:06-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:57:07 volumio volumio[22103]: info: Loading plugin "squeezelite_mc"... Dec 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57: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 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57: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 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57:07-06:00" level=info msg="zeroconf server listening on port 38463" Dec 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57:07-06:00" level=debug msg="obtained new client token: AABbEjiF6qFIAsP10btf2WYwMH7jGaC/RyA1qFR0dK0Wp2/XSarquMYrg11ujLb56zZlm9w/jOiwHtKTGL9mO60zmlAtYtkdsDnSmbCbT9njL7BeqR4bn3VzYn1Fn8KgBlRVqRyKAXZ/i8gQ6G5SXnq+EwtPVVJaYuyBhqV5jUe/1zP/X0Fd7LKpI6CAjdOG+xag2hkNq6UGx9KYug/X+hkiCqGq3j4BQQhFWU6FXN1m/NU9MwXgz0w=" Dec 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57:07-06:00" level=debug msg="completed keyexchange" Dec 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57:07-06:00" level=debug msg="completed challenge" Dec 30 17:57:07 volumio go-librespot[22260]: time="2025-12-30T17:57:07-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:57:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:57:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:57:07 volumio volumio[22103]: info: Loading plugin "youtube2"... Dec 30 17:57:08 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 17:57:08 volumio volumio[22103]: info: Loading plugin "ytcr"... Dec 30 17:57:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Dec 30 17:57:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:10 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.83.206 Dec 30 17:57:10 volumio avahi-daemon[664]: Registering new address record for 169.254.83.206 on eth0.IPv4. Dec 30 17:57:10 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:57:10 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:10 volumio go-librespot[22281]: go-librespot daemon starting... Dec 30 17:57:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:10 volumio go-librespot[22290]: time="2025-12-30T17:57:10-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:57:10 volumio go-librespot[22290]: time="2025-12-30T17:57:10-06:00" level=debug msg="app state loaded" Dec 30 17:57:10 volumio go-librespot[22290]: time="2025-12-30T17:57:10-06:00" level=debug msg="stored credentials not found" Dec 30 17:57:10 volumio go-librespot[22290]: time="2025-12-30T17:57:10-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:57:10 volumio volumio[22103]: info: Loading plugin "ytmusic"... Dec 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-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 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-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 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-06:00" level=info msg="zeroconf server listening on port 42547" Dec 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-06:00" level=debug msg="obtained new client token: AADgkOLVBn8QKqUP3fYPbeLxgdrf+b08PxurnZNFjAJTkQAD9CQ1KskyKKvzSznpeuXl1yE1DsW5ISf9nV3QA+BBADGISwyj8l/ptjCw9XBuWAc/cvaJzmbv4uiA7utIWNQe1INlmZT1Mn1zhvylQWq+obCItEn6OHlwCJAkDfFTVgtJpmnqJhMN195AR33GHASspfWfG3eEkv35Rdiqsao7xGYLUl3JNWniN1UXnKNtIj3guYLB5zM=" Dec 30 17:57:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.83.206 Dec 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-06:00" level=debug msg="completed keyexchange" Dec 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-06:00" level=debug msg="completed challenge" Dec 30 17:57:11 volumio go-librespot[22290]: time="2025-12-30T17:57:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:57:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:57:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:57:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.83.206 Dec 30 17:57:11 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.83.206 Dec 30 17:57:11 volumio avahi-daemon[664]: Withdrawing address record for 169.254.83.206 on eth0. Dec 30 17:57:11 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:57:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:11 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:57:11 volumio volumio[22103]: info: Plugin now_playing is not enabled Dec 30 17:57:11 volumio volumio[22103]: info: Loading plugin "outputs"... Dec 30 17:57:11 volumio volumio[22103]: info: Loading plugin "albumart"... Dec 30 17:57:11 volumio volumio[22103]: info: Plugin example_plugin is not enabled Dec 30 17:57:11 volumio volumio[22103]: info: Loading plugin "inputs"... Dec 30 17:57:11 volumio volumio[22103]: info: Loading plugin "updater_comm"... Dec 30 17:57:11 volumio volumio[22103]: info: Plugin mpdemulation is not enabled Dec 30 17:57:11 volumio volumio[22103]: info: Loading plugin "rest_api"... Dec 30 17:57:11 volumio volumio[22103]: info: Loading plugin "websocket"... Dec 30 17:57:11 volumio volumio[22103]: info: Starting Socket.io Server version 1.7.4 Dec 30 17:57:11 volumio volumio[22103]: info: Plugin fusiondsp is not enabled Dec 30 17:57:11 volumio volumio[22103]: info: Plugin mpdoutput is not enabled Dec 30 17:57:11 volumio volumio[22103]: info: Plugin RoonBridge is not enabled Dec 30 17:57:11 volumio volumio[22103]: info: Loading plugin "podcast"... Dec 30 17:57:12 volumio volumio[22103]: info: ControllerPodcast::constructor Dec 30 17:57:12 volumio volumio[22103]: info: Loading plugin "volusonic"... Dec 30 17:57:12 volumio volumio[22323]: Forking 3 albumart workers Dec 30 17:57:13 volumio volumio-remote-updater[702]: [2025-12-30 17:57:13] [connect] Successful connection Dec 30 17:57:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Dec 30 17:57:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:14 volumio go-librespot[22363]: go-librespot daemon starting... Dec 30 17:57:14 volumio volumio[22103]: info: Applying required configuration parameters for plugin volusonic Dec 30 17:57:14 volumio volumio[22103]: info: Loading plugin "backup_restore"... Dec 30 17:57:14 volumio go-librespot[22364]: time="2025-12-30T17:57:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:57:14 volumio go-librespot[22364]: time="2025-12-30T17:57:14-06:00" level=debug msg="app state loaded" Dec 30 17:57:14 volumio go-librespot[22364]: time="2025-12-30T17:57:14-06:00" level=debug msg="stored credentials not found" Dec 30 17:57:14 volumio go-librespot[22364]: time="2025-12-30T17:57:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:57:15 volumio volumio[22335]: Starting albumart workers Dec 30 17:57:15 volumio volumio[22333]: Starting albumart workers Dec 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-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 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-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 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-06:00" level=info msg="zeroconf server listening on port 40667" Dec 30 17:57:15 volumio volumio[22103]: info: Applying required configuration parameters for plugin backup_restore Dec 30 17:57:15 volumio volumio[22103]: info: Plugin rpi_eeprom_config is not enabled Dec 30 17:57:15 volumio volumio[22103]: info: Plugin rpi_eeprom_updater is not enabled Dec 30 17:57:15 volumio volumio[22103]: info: Loading plugin "scheduledrestart"... Dec 30 17:57:15 volumio volumio[22334]: Starting albumart workers Dec 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-06:00" level=debug msg="obtained new client token: AADd2ZxO42ve3io4yoQoAaJue00kkC6+BK8hqMpQ8yst6KxC22mI8KysguHPPeqLZN13rDBNKvHJZ6wALi1Pi5ju4BuLvuHxchNFoSKlnpmS436eeO0pzc2YZ5BrBIrsdt00USpXCh3SWpKruSiUs/y5IfZOmnDVxi8yhFVOZaO3QclkOkjMHxzeFMVkGFEAn5fAmawb9hMUbZe9SRQNoeqE6wkd1dTyJ4rNv6LaOFQ8LenMZ64tjqBdgw==" Dec 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-06:00" level=debug msg="completed keyexchange" Dec 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-06:00" level=debug msg="completed challenge" Dec 30 17:57:15 volumio go-librespot[22364]: time="2025-12-30T17:57:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:57:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:57:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:57:15 volumio volumio[22103]: info: Applying required configuration parameters for plugin scheduledrestart Dec 30 17:57:15 volumio volumio[22103]: info: Plugin Bluetoothremote is not enabled Dec 30 17:57:15 volumio volumio[22103]: info: Plugin music_services_shield is not enabled Dec 30 17:57:15 volumio volumio[22103]: info: Loading plugin "Systeminfo"... Dec 30 17:57:16 volumio volumio[22103]: info: Plugin peppymeterbasic is not enabled Dec 30 17:57:16 volumio volumio[22103]: info: Loading plugin "peppyspectrum"... Dec 30 17:57:16 volumio volumio[22103]: info: Loading i18n strings for locale en Dec 30 17:57:16 volumio volumio[22103]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 17:57:16 volumio volumio[22103]: Updating browse sources language Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::initPlayerControls Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:57:16 volumio volumio[22103]: Express server listening on port 3000 Dec 30 17:57:16 volumio volumio[22103]: [Metrics] WebUI: 19s 130.34ms Dec 30 17:57:16 volumio volumio[22103]: info: CoreStateMachine::resetVolumioState Dec 30 17:57:16 volumio volumio[22103]: info: CoreStateMachine::getcurrentVolume Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 17:57:16 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:16 volumio sudo[22394]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 30 17:57:16 volumio sudo[22394]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:16 volumio sudo[22394]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:16 volumio sudo[22396]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 30 17:57:16 volumio sudo[22396]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:16 volumio sudo[22396]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:16 volumio volumio[22103]: info: Volumio Network Manager: Network status updated: 1 Dec 30 17:57:17 volumio volumio[22103]: info: VolumeController:: Volume=100 Mute =false Dec 30 17:57:17 volumio volumio[22103]: info: CoreStateMachine::pushState Dec 30 17:57:17 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioPushState Dec 30 17:57:17 volumio volumio[22103]: info: CoreStateMachine::updateTrackBlock Dec 30 17:57:17 volumio volumio[22103]: info: CorePlayQueue::getTrackBlock Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 17:57:17 volumio volumio-remote-updater[702]: [2025-12-30 17:57:17] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767139033 101 Dec 30 17:57:17 volumio volumio[22103]: 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 30 17:57:17 volumio volumio[22103]: info: Reloading queue from file Dec 30 17:57:17 volumio volumio[22103]: info: CoreStateMachine::setRepeat null single undefined Dec 30 17:57:17 volumio volumio[22103]: info: CoreStateMachine::pushState Dec 30 17:57:17 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioPushState Dec 30 17:57:17 volumio volumio[22103]: info: CoreStateMachine::setRandom null Dec 30 17:57:17 volumio volumio[22103]: info: CoreStateMachine::pushState Dec 30 17:57:17 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioPushState Dec 30 17:57:17 volumio volumio[22103]: info: Setting Device type: Raspberry PI Dec 30 17:57:17 volumio volumio[22103]: info: VolumeController:: Volume=100 Mute =false Dec 30 17:57:17 volumio volumio[22103]: info: CoreStateMachine::pushState Dec 30 17:57:17 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioPushState Dec 30 17:57:17 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.31.213 Dec 30 17:57:17 volumio avahi-daemon[664]: Registering new address record for 169.254.31.213 on eth0.IPv4. Dec 30 17:57:17 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:57:17 volumio volumio[22103]: info: Completed loading Core Plugins Dec 30 17:57:17 volumio volumio[22103]: info: Preparing to generate the ALSA configuration file Dec 30 17:57:17 volumio sudo[22413]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 30 17:57:17 volumio sudo[22413]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:17 volumio volumio[22103]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 17:57:17 volumio volumio[22103]: info: Discovery: Found device Volumio Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioGetState Dec 30 17:57:17 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:17 volumio volumio[22103]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 30 17:57:17 volumio sudo[22413]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:17 volumio volumio[22103]: info: Discovery: Found device Volumio Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioGetState Dec 30 17:57:17 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:17 volumio volumio[22103]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 17:57:17 volumio volumio[22103]: info: Reading ALSA contributions from plugins. Dec 30 17:57:17 volumio volumio[22103]: info: Upmpdcli Daemon Started Dec 30 17:57:17 volumio volumio[22103]: info: Asound.conf file unchanged, so no further update is needed Dec 30 17:57:17 volumio volumio[22103]: info: Output device has changed, restarting MPD Dec 30 17:57:17 volumio volumio[22103]: info: Output device has changed, restarting Shairport Sync Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:17 volumio sudo[22429]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 17:57:17 volumio sudo[22429]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:17 volumio sudo[22429]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:17 volumio sudo[22431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 17:57:17 volumio sudo[22431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:17 volumio volumio[22103]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:57:17 volumio volumio[22103]: info: ___________ START PLUGINS ___________ Dec 30 17:57:17 volumio volumio[22103]: info: ControllerMpd::onStart: Initializing MPD Dec 30 17:57:17 volumio volumio[22103]: info: Creating MPD Configuration file Dec 30 17:57:17 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.31.213 Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:17 volumio volumio[22103]: info: [1767139037408] CoreMusicLibrary::Adding element Media Servers Dec 30 17:57:17 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:17 volumio sudo[22439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 17:57:17 volumio sudo[22439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:17 volumio sudo[22441]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 17:57:17 volumio sudo[22441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:17 volumio sudo[22439]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:17 volumio volumio[22103]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:17 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 17:57:17 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 17:57:17 volumio systemd[1]: mpd.service: Consumed 4.386s CPU time. Dec 30 17:57:17 volumio volumio[22103]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:57:17 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 17:57:17 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 17:57:17 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:17 volumio volumio[22103]: info: [1767139037534] CoreMusicLibrary::Adding element Last_100 Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:17 volumio volumio[22103]: info: [1767139037540] CoreMusicLibrary::Adding element Webradio Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 17:57:17 volumio volumio[22103]: info: Initializing BBC Radios Dec 30 17:57:17 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 17:57:17 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:17 volumio volumio[22103]: info: [1767139037625] CoreMusicLibrary::Adding element Bandcamp Discover Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:17 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:17 volumio volumio[22103]: info: [1767139037636] CoreMusicLibrary::Adding element SoundCloud Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:17 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:17 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:17 volumio volumio[22103]: info: Creating Spotify config file Dec 30 17:57:17 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:17 volumio sudo[22461]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 17:57:17 volumio sudo[22461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 17:57:17 volumio sudo[22461]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:17 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.31.213 Dec 30 17:57:17 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.31.213 Dec 30 17:57:17 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:57:17 volumio avahi-daemon[664]: Withdrawing address record for 169.254.31.213 on eth0. Dec 30 17:57:17 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:57:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:18 volumio volumio[22103]: info: [squeezelite_mc] Starting proxy server... Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:18 volumio volumio[22103]: info: [1767139038025] CoreMusicLibrary::Adding element YouTube2 Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube2 Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:18 volumio volumio[22103]: info: [1767139038043] CoreMusicLibrary::Adding element YouTube Music Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube2 Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube Music Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:18 volumio volumio[22103]: info: [1767139038055] CoreMusicLibrary::Adding element Podcast Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube2 Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube Music Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Podcast Dec 30 17:57:18 volumio volumio[22103]: info: Loading i18n strings for locale en Dec 30 17:57:18 volumio volumio[22103]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 30 17:57:18 volumio volumio[22103]: Updating browse sources language Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube2 Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube Music Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Podcast Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube2 Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube Music Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Podcast Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:18 volumio volumio[22103]: info: [1767139038102] CoreMusicLibrary::Adding element Volusonic Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube2 Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source YouTube Music Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Podcast Dec 30 17:57:18 volumio volumio[22103]: Cannot find translation for source Volusonic Dec 30 17:57:18 volumio volumio[22103]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 30 17:57:18 volumio volumio[22103]: info: Volumio Calling Home Dec 30 17:57:18 volumio volumio[22103]: info: [squeezelite_mc] Proxy server started on port 34925 Dec 30 17:57:18 volumio volumio[22103]: info: Preparing to generate the ALSA configuration file Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::volumioRetrievevolume Dec 30 17:57:18 volumio volumio[22103]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 30 17:57:18 volumio volumio[22103]: info: Reading ALSA contributions from plugins. Dec 30 17:57:18 volumio volumio[22103]: info: MPD Permissions set Dec 30 17:57:18 volumio volumio[22103]: info: MPD Permissions set Dec 30 17:57:18 volumio volumio[22103]: info: Spotify config file written Dec 30 17:57:18 volumio volumio[22103]: 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 30 17:57:18 volumio sudo[22492]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 30 17:57:18 volumio sudo[22492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:18 volumio volumio[22103]: info: VolumeController:: Volume=100 Mute =false Dec 30 17:57:18 volumio volumio[22103]: info: CoreStateMachine::pushState Dec 30 17:57:18 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::volumioPushState Dec 30 17:57:18 volumio volumio[22103]: info: [squeezelite_mc] Server discovery started Dec 30 17:57:18 volumio volumio[22103]: info: [squeezelite_mc] Player finder started Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:18 volumio volumio[22103]: info: No need to fix Spotify hosts Dec 30 17:57:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:18 volumio go-librespot[22497]: go-librespot daemon starting... Dec 30 17:57:18 volumio sudo[22492]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=debug msg="app state loaded" Dec 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=debug msg="stored credentials not found" Dec 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:57:18 volumio kernel: hwmon hwmon1: Voltage normalised Dec 30 17:57:18 volumio volumio[22103]: 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 30 17:57:18 volumio volumio[22103]: info: Volumio called home Dec 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 30 17:57:18 volumio volumio[22103]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 30 17:57:18 volumio volumio[22103]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 30 17:57:18 volumio volumio[22103]: 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 30 17:57:18 volumio go-librespot[22507]: time="2025-12-30T17:57:18-06:00" level=info msg="zeroconf server listening on port 37965" Dec 30 17:57:18 volumio volumio[22103]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 17:57:18 volumio volumio[22103]: SPOTIFY: BQBW9lBFIqF01mrCtvZoFJXfYxk4DPzinm7nRCHOkXFwpLRlULtzCGp9F6tQvlcllPs0yniWFRdE2AXNILOWkPRfCXZ9IDStFVEi6f7fDginy9lLi_JGS6u4CzKzC9yWxv0qGdGDPkrbk-Uee_tHENsXipkTmeafnuoabISwFHQXqO2VbfhpkgFNAqXb2iT_41zldw5-WtRBNPSpigIfzzu0R6YK9UmcR7OMTvk Dec 30 17:57:18 volumio volumio[22103]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 30 17:57:18 volumio volumio[22103]: info: New Spotify access token = BQBW9lBFIqF01mrCtvZoFJXfYxk4DPzinm7nRCHOkXFwpLRlULtzCGp9F6tQvlcllPs0yniWFRdE2AXNILOWkPRfCXZ9IDStFVEi6f7fDginy9lLi_JGS6u4CzKzC9yWxv0qGdGDPkrbk-Uee_tHENsXipkTmeafnuoabISwFHQXqO2VbfhpkgFNAqXb2iT_41zldw5-WtRBNPSpigIfzzu0R6YK9UmcR7OMTvk Dec 30 17:57:18 volumio volumio[22103]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 30 17:57:19 volumio sudo[22518]: 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 30 17:57:19 volumio sudo[22518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio sudo[22518]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:19 volumio volumio[22103]: info: Starting Shairport Sync Dec 30 17:57:19 volumio volumio[22103]: info: Starting Shairport Sync Dec 30 17:57:19 volumio volumio[22103]: info: Starting Shairport Sync Dec 30 17:57:19 volumio go-librespot[22507]: time="2025-12-30T17:57:19-06:00" level=debug msg="obtained new client token: AABSntEB0bMmu3x1PIUOsaV/qUU7gT6k7S//OGJJGdgrfWoy/cxpT1Ljb1glAyVg+zXYv5B5AbKnkNFqkPfQwskVADH6f+Njc3T2O3tAzvqyrvcKyiEHBALs8+yCOv6JWeMiv4rQ0XdXs0aFHOt1iogyoPKw7cjdbcBkebiSzo/rvK5FhN6ViWuID3myIlgymprJ0FkY6Qq2BLQMTNvZcI0dEelNi/pcSgcUXkm3LZJxWXJIvmk4rzg=" Dec 30 17:57:19 volumio sudo[22523]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:57:19 volumio sudo[22523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio sudo[22521]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:57:19 volumio sudo[22521]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio go-librespot[22507]: time="2025-12-30T17:57:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:57:19 volumio sudo[22525]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:57:19 volumio sudo[22525]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio go-librespot[22507]: time="2025-12-30T17:57:19-06:00" level=debug msg="completed keyexchange" Dec 30 17:57:19 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 17:57:19 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 17:57:19 volumio go-librespot[22507]: time="2025-12-30T17:57:19-06:00" level=debug msg="completed challenge" Dec 30 17:57:19 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:57:19 volumio systemd[1]: shairport-sync.service: Consumed 2.151s CPU time. Dec 30 17:57:19 volumio go-librespot[22507]: time="2025-12-30T17:57: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 30 17:57:19 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:57:19 volumio volumio[22103]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 30 17:57:19 volumio sudo[22521]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:19 volumio sudo[22523]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:57:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:57:19 volumio volumio[22103]: info: Asound.conf file unchanged, so no further update is needed Dec 30 17:57:19 volumio volumio[22103]: info: Output device has changed, restarting MPD Dec 30 17:57:19 volumio sudo[22525]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:19 volumio sudo[22536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 30 17:57:19 volumio sudo[22536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio sudo[22534]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 30 17:57:19 volumio sudo[22534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio sudo[22536]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:19 volumio volumio[22103]: info: Output device has changed, restarting Shairport Sync Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:19 volumio sudo[22534]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:19 volumio sudo[22552]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 30 17:57:19 volumio sudo[22552]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio volumio[22103]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 30 17:57:19 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 30 17:57:19 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 30 17:57:19 volumio systemd[1]: mpd.service: Consumed 1.723s CPU time. Dec 30 17:57:19 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 30 17:57:19 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 30 17:57:19 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 30 17:57:19 volumio volumio[22103]: info: Shairport-Sync Started Dec 30 17:57:19 volumio volumio[22103]: Error adding Membership: Error: addMembership EINVAL Dec 30 17:57:19 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 30 17:57:19 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 30 17:57:19 volumio volumio[22103]: info: MPD Permissions set Dec 30 17:57:19 volumio volumio[22103]: 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 30 17:57:19 volumio volumio[22103]: info: Shairport-Sync Started Dec 30 17:57:19 volumio volumio[22103]: info: Shairport-Sync Started Dec 30 17:57:19 volumio sudo[22567]: 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 30 17:57:19 volumio sudo[22567]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio sudo[22567]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:19 volumio volumio[22103]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio sudo[22570]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 30 17:57:19 volumio sudo[22570]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:19 volumio systemd[1]: Reloading. Dec 30 17:57:19 volumio volumio[22103]: info: CoreCommandRouter::volumioGetState Dec 30 17:57:19 volumio volumio[22103]: info: CorePlayQueue::getTrack 0 Dec 30 17:57:19 volumio volumio[22103]: info: Starting Shairport Sync Dec 30 17:57:19 volumio sudo[22564]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 30 17:57:19 volumio sudo[22564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 30 17:57:19 volumio sudo[22564]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:20 volumio sudo[22579]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 30 17:57:20 volumio sudo[22579]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:20 volumio volumio[22103]: 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 30 17:57:20 volumio volumio[22103]: info: Spotify Successfully logged in Dec 30 17:57:20 volumio volumio[22103]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 30 17:57:20 volumio volumio[22103]: info: [1767139040319] CoreMusicLibrary::Adding element Spotify Dec 30 17:57:20 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 30 17:57:20 volumio volumio[22103]: Cannot find translation for source Bandcamp Discover Dec 30 17:57:20 volumio volumio[22103]: Cannot find translation for source SoundCloud Dec 30 17:57:20 volumio volumio[22103]: Cannot find translation for source YouTube2 Dec 30 17:57:20 volumio volumio[22103]: Cannot find translation for source YouTube Music Dec 30 17:57:20 volumio volumio[22103]: Cannot find translation for source Podcast Dec 30 17:57:20 volumio volumio[22103]: Cannot find translation for source Volusonic Dec 30 17:57:20 volumio volumio[22103]: Cannot find translation for source Spotify Dec 30 17:57:20 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 30 17:57:20 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:20 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:20 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 30 17:57:20 volumio volumio[22103]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 30 17:57:21 volumio volumio[22103]: info: go-librespot daemon successfully initialized Dec 30 17:57:22 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 30 17:57:22 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 30 17:57:23 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.179.19 Dec 30 17:57:23 volumio avahi-daemon[664]: Registering new address record for 169.254.179.19 on eth0.IPv4. Dec 30 17:57:23 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Dec 30 17:57:23 volumio sudo[22570]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:23 volumio volumio[22103]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 30 17:57:23 volumio sudo[22632]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 30 17:57:23 volumio sudo[22632]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 30 17:57:23 volumio volumio[22103]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 17:57:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Dec 30 17:57:23 volumio volumio[22103]: Error: addMembership ENODEV Dec 30 17:57:23 volumio volumio[22103]: at Socket.addMembership (node:dgram:860:11) Dec 30 17:57:23 volumio volumio[22103]: at addMembership (/volumio/node_modules/node-ssdp/lib/index.js:264:16) { Dec 30 17:57:23 volumio volumio[22103]: errno: -19, Dec 30 17:57:23 volumio volumio[22103]: code: 'ENODEV', Dec 30 17:57:23 volumio volumio[22103]: syscall: 'addMembership' Dec 30 17:57:23 volumio volumio[22103]: } Dec 30 17:57:23 volumio volumio[22103]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 30 17:57:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.179.19 Dec 30 17:57:23 volumio sudo[22632]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 30 17:57:23 volumio go-librespot[22646]: go-librespot daemon starting... Dec 30 17:57:23 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 30 17:57:23 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 30 17:57:23 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:57:23 volumio systemd[1]: shairport-sync.service: Consumed 1.453s CPU time. Dec 30 17:57:23 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 30 17:57:23 volumio sudo[22579]: pam_unix(sudo:session): session closed for user root Dec 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-06:00" level=info msg="running go-librespot 0.4.0" Dec 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-06:00" level=debug msg="app state loaded" Dec 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-06:00" level=debug msg="stored credentials not found" Dec 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 30 17:57:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.179.19 Dec 30 17:57:23 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.179.19 Dec 30 17:57:23 volumio avahi-daemon[664]: Withdrawing address record for 169.254.179.19 on eth0. Dec 30 17:57:23 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Dec 30 17:57:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Dec 30 17:57:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Dec 30 17:57:23 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Dec 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-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 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-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 30 17:57:23 volumio go-librespot[22647]: time="2025-12-30T17:57:23-06:00" level=info msg="zeroconf server listening on port 33279" Dec 30 17:57:24 volumio go-librespot[22647]: time="2025-12-30T17:57:24-06:00" level=debug msg="obtained new client token: AADmoV9ism4lVV6mbrwPplPNJbTTdAlZ4aqc6pAJMfP6kbxglfD4DCRmnspXezspQ9cflLyHkzdnmL8IA5IZ5x9TbvD5SfNBvUkJZwL+p5xkSSx4AM2D097FZ5+2S8SyXzzFZ7uYrg/YI+BkK9YE2QEnmhuI44lGq4+PBIfnRyyWweCCn2v+SMBO7Vfw+TPmAWQsrWFm5ahq+ofBPTopRL7cpCTjZy66UOposQMvN7bS9e3rZmXFSXA=" Dec 30 17:57:24 volumio go-librespot[22647]: time="2025-12-30T17:57:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 30 17:57:24 volumio go-librespot[22647]: time="2025-12-30T17:57:24-06:00" level=debug msg="completed keyexchange" Dec 30 17:57:24 volumio go-librespot[22647]: time="2025-12-30T17:57:24-06:00" level=debug msg="completed challenge" Dec 30 17:57:24 volumio go-librespot[22647]: time="2025-12-30T17:57:24-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Dec 30 17:57:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 30 17:57:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 30 17:57:24 volumio sudo[22688]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-30 17:56' Dec 30 17:57:24 volumio sudo[22688]: 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"