Jan 10 01:34:00 volumio volumio[7034]: info: Getting Spotify volume Jan 10 01:34:00 volumio volumio[7034]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 01:34:00 volumio volumio[7034]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:34:00 volumio volumio[7034]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 10 01:34:00 volumio volumio[7034]: errno: -111, Jan 10 01:34:00 volumio volumio[7034]: code: 'ECONNREFUSED', Jan 10 01:34:00 volumio volumio[7034]: syscall: 'connect', Jan 10 01:34:00 volumio volumio[7034]: address: '127.0.0.1', Jan 10 01:34:00 volumio volumio[7034]: port: 9879, Jan 10 01:34:00 volumio volumio[7034]: response: undefined Jan 10 01:34:00 volumio volumio[7034]: } Jan 10 01:34:00 volumio volumio[7034]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 01:34:00 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.5.202 Jan 10 01:34:00 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:00 volumio avahi-daemon[664]: Registering new address record for 169.254.5.202 on eth0.IPv4. Jan 10 01:34:00 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:00 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:00 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:00 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.5.202 Jan 10 01:34:00 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.5.202 Jan 10 01:34:00 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.5.202 Jan 10 01:34:00 volumio avahi-daemon[664]: Withdrawing address record for 169.254.5.202 on eth0. Jan 10 01:34:00 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Jan 10 01:34:00 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:00 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:01 volumio go-librespot[7974]: go-librespot daemon starting... Jan 10 01:34:01 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:01 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:01 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=debug msg="app state loaded" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34: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]" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34: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]" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34: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]" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=info msg="zeroconf server listening on port 46673" Jan 10 01:34:01 volumio sudo[7984]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 01:33' Jan 10 01:34:01 volumio sudo[7984]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=debug msg="obtained new client token: AACfiyx/XW4j7SHk1OdlyXw9ENm2lUUOrbf/ayKaSRPMqa81mjzYFtpJ1Vj+bCZfXJt56IMvBmusJbwl6PFM3T7yqMzzldksxRYB9sMQJGF6KuY3RJ6uobY2WRZC6dDk1BqKF90gP3MuOhQLf/NlBFw6Bf9DwaVMfnJ7Bg8cYy4ND8IUtmkJkas6cm1Udf/xnEqyU5uB9EBC14skvoxypL0m8+bvZIefCe1BVwLuOQh5XYI5Vv2N0ztomg==" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:01 volumio sudo[7984]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34:01-06:00" level=debug msg="completed challenge" Jan 10 01:34:01 volumio go-librespot[7975]: time="2026-01-10T01:34: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 " Jan 10 01:34:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:01 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 01:34:01 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 01:34:01 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:01 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 01:34:01 volumio systemd[1]: volumio.service: Consumed 54.841s CPU time. Jan 10 01:34:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 01:34:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 01:34:01 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 17357. Jan 10 01:34:01 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 01:34:01 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 01:34:01 volumio systemd[1]: volumio.service: Consumed 54.841s CPU time. Jan 10 01:34:01 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 01:34:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 01:34:03 volumio volumio[8011]: info: ------------------------------------------- Jan 10 01:34:03 volumio volumio[8011]: info: ----- Volumio3 ---- Jan 10 01:34:03 volumio volumio[8011]: info: ------------------------------------------- Jan 10 01:34:03 volumio volumio[8011]: info: ----- System startup ---- Jan 10 01:34:03 volumio volumio[8011]: info: ------------------------------------------- Jan 10 01:34:04 volumio volumio[8011]: info: MYVOLUMIO Environment detected Jan 10 01:34:04 volumio volumio[8011]: info: Plugin folders cleanup Jan 10 01:34:04 volumio volumio[8011]: info: Scanning into folder /volumio/app/plugins/ Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category audio_interface Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category miscellanea Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category music_service Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category plugins.json Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category system_controller Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category user_interface Jan 10 01:34:04 volumio volumio[8011]: info: Scanning into folder /data/plugins/ Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category audio_interface Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category music_service Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category system_controller Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category system_hardware Jan 10 01:34:04 volumio volumio[8011]: info: Scanning category user_interface Jan 10 01:34:04 volumio volumio[8011]: info: Plugin folders cleanup completed Jan 10 01:34:04 volumio volumio[8011]: info: ------------------------------------------- Jan 10 01:34:04 volumio volumio[8011]: info: ----- Core plugins startup ---- Jan 10 01:34:04 volumio volumio[8011]: info: ------------------------------------------- Jan 10 01:34:04 volumio volumio[8011]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 01:34:04 volumio volumio[8011]: info: Adding plugin upnp to MyMusic Plugins Jan 10 01:34:04 volumio volumio[8011]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 01:34:04 volumio volumio[8011]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 01:34:04 volumio volumio[8011]: info: Loading plugins from folder /data/plugins/ Jan 10 01:34:04 volumio volumio[8011]: info: Loading plugin "system"... Jan 10 01:34:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Jan 10 01:34:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:04 volumio volumio[8011]: info: Loading plugin "appearance"... Jan 10 01:34:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:04 volumio go-librespot[8038]: go-librespot daemon starting... Jan 10 01:34:04 volumio go-librespot[8042]: time="2026-01-10T01:34:04-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:04 volumio go-librespot[8042]: time="2026-01-10T01:34:04-06:00" level=debug msg="app state loaded" Jan 10 01:34:04 volumio go-librespot[8042]: time="2026-01-10T01:34:04-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:04 volumio go-librespot[8042]: time="2026-01-10T01:34:04-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=info msg="zeroconf server listening on port 32803" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=debug msg="obtained new client token: AACgXNCzCK8KLVNlgfjJP4eb16XZ4L0UovHI8eU8IE2/5CPrjHL5LXqhtNPIko+f2k4clfNa//RU78PGDVd97sl3asB8Mts7bF06+P4/VVHhOdSNJ4OW/Wk5em2eo2wTctG7w9GscEcxHfYydrjwSXjTckDxEYtgazQY+hwmJGd23YvF/kDtdHs39L3XkX9HbFtDNfLw+pcecNnj+Y2axXGv1rfFTma1K+VQIFY6tVAjrlwsCqJMwoQ=" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34:05-06:00" level=debug msg="completed challenge" Jan 10 01:34:05 volumio go-librespot[8042]: time="2026-01-10T01:34: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 " Jan 10 01:34:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:05 volumio volumio[8011]: info: Loading plugin "network"... Jan 10 01:34:05 volumio volumio[8011]: info: Refreshing Cached IP Addresses Jan 10 01:34:05 volumio sudo[8050]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 01:34:05 volumio sudo[8050]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:05 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.46.232 Jan 10 01:34:05 volumio avahi-daemon[664]: Registering new address record for 169.254.46.232 on eth0.IPv4. Jan 10 01:34:05 volumio sudo[8050]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:05 volumio sudo[8052]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 01:34:05 volumio sudo[8052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:05 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:05 volumio volumio[8011]: info: Loading plugin "services"... Jan 10 01:34:05 volumio volumio[8011]: info: Loading plugin "alsa_controller"... Jan 10 01:34:05 volumio sudo[8052]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:05 volumio sudo[8060]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 01:34:05 volumio sudo[8060]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:05 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:05 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:05 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:06 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:34:06 volumio volumio[8011]: info: Loading plugin "wizard"... Jan 10 01:34:06 volumio volumio[8011]: info: Loading plugin "networkfs"... Jan 10 01:34:06 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.46.232 Jan 10 01:34:06 volumio volumio[8011]: info: Starting Udev Watcher for removable devices Jan 10 01:34:06 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 01:34:06 volumio volumio[8011]: info: Ignoring mount for partition: boot Jan 10 01:34:06 volumio volumio[8011]: info: Ignoring mount for partition: volumio Jan 10 01:34:06 volumio volumio[8011]: info: Ignoring mount for partition: volumio_data Jan 10 01:34:06 volumio volumio[8011]: info: Mounting Device Wikipedia Jan 10 01:34:06 volumio sudo[8106]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 10 01:34:06 volumio sudo[8106]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:06 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.46.232 Jan 10 01:34:06 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.46.232 Jan 10 01:34:06 volumio avahi-daemon[664]: Withdrawing address record for 169.254.46.232 on eth0. Jan 10 01:34:06 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:06 volumio sudo[8106]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:06 volumio volumio[8011]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 01:34:06 volumio volumio[8011]: dmesg(1) may have more information after failed mount system call. Jan 10 01:34:06 volumio volumio[8011]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 10 01:34:06 volumio volumio[8011]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 01:34:06 volumio volumio[8011]: dmesg(1) may have more information after failed mount system call. Jan 10 01:34:06 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 01:34:06 volumio volumio[8011]: info: Loading plugin "volumio_command_line_client"... Jan 10 01:34:06 volumio volumio[8011]: info: Loading plugin "upnp"... Jan 10 01:34:06 volumio volumio[8011]: info: [1768030446291] Starting Upmpd Daemon Jan 10 01:34:06 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 01:34:06 volumio volumio[8011]: info: Loading plugin "my_music"... Jan 10 01:34:06 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:06 volumio volumio[8011]: info: Loading plugin "mpd"... Jan 10 01:34:06 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:06 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:06 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:06 volumio sudo[8060]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:06 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:06] [connect] Successful connection Jan 10 01:34:06 volumio volumio[8011]: info: Loading plugin "upnp_browser"... Jan 10 01:34:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Jan 10 01:34:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:08 volumio go-librespot[8124]: go-librespot daemon starting... Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-06:00" level=debug msg="app state loaded" Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-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]" Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-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]" Jan 10 01:34:08 volumio go-librespot[8125]: time="2026-01-10T01:34:08-06:00" level=info msg="zeroconf server listening on port 35393" Jan 10 01:34:09 volumio go-librespot[8125]: time="2026-01-10T01:34:09-06:00" level=debug msg="obtained new client token: AAARHUgHvgO6qj9ZtqNgINOBwNZ6YGmuZPt1sMZpxi2kqPTQfd6Agt1u9tVVL9buz3KZdx6KlYeIzKqhtHklGE8Bj+r8Cm8ByO1dEDe2WcYiw4yy0YT5p/h/aonX82N8wqJ3MasAXBXnzRxLcFpaH2Oy/kvHcirucy39j3/2KUHV6TNtTWHkJ334pxTeuHMrB8hct52vZQnfRsviG7lRuqKXa+jT65+UMVL1fhdswi6swQ5sUwcAWwA=" Jan 10 01:34:09 volumio go-librespot[8125]: time="2026-01-10T01:34:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:09 volumio go-librespot[8125]: time="2026-01-10T01:34:09-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:09 volumio go-librespot[8125]: time="2026-01-10T01:34:09-06:00" level=debug msg="completed challenge" Jan 10 01:34:09 volumio go-librespot[8125]: time="2026-01-10T01:34: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 " Jan 10 01:34:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:09 volumio volumio[8011]: info: Loading plugin "alarm-clock"... Jan 10 01:34:09 volumio volumio[8011]: info: Loading plugin "airplay_emulation"... Jan 10 01:34:09 volumio volumio[8011]: info: Starting Shairport Sync Jan 10 01:34:09 volumio volumio[8011]: info: Loading plugin "last_100"... Jan 10 01:34:09 volumio volumio[8011]: info: Loading plugin "webradio"... Jan 10 01:34:09 volumio volumio[8011]: info: Loading plugin "i2s_dacs"... Jan 10 01:34:09 volumio volumio[8011]: info: I2S DAC not set, start Auto-detection Jan 10 01:34:09 volumio volumio[8011]: info: Loading plugin "volumiodiscovery"... Jan 10 01:34:09 volumio volumio[8011]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:09 volumio volumio[8011]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:09 volumio volumio[8011]: *** WARNING *** For more information see Jan 10 01:34:09 volumio volumio[8011]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:09 volumio volumio[8011]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:09 volumio volumio[8011]: *** WARNING *** For more information see Jan 10 01:34:09 volumio node[8011]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:09 volumio node[8011]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:09 volumio node[8011]: *** WARNING *** For more information see Jan 10 01:34:09 volumio node[8011]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:09 volumio node[8011]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:09 volumio node[8011]: *** WARNING *** For more information see Jan 10 01:34:09 volumio volumio[8011]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 01:34:09 volumio volumio[8011]: info: Discovery: Started advertising with name: Volumio Jan 10 01:34:09 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 01:34:09 volumio volumio[8011]: info: Loading plugin "bandcamp"... Jan 10 01:34:10 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.59.3 Jan 10 01:34:10 volumio avahi-daemon[664]: Registering new address record for 169.254.59.3 on eth0.IPv4. Jan 10 01:34:10 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:10 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:10 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:10 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:10 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.59.3 Jan 10 01:34:11 volumio volumio[8011]: info: Plugin calmradio is not enabled Jan 10 01:34:11 volumio volumio[8011]: info: Loading plugin "soundcloud"... Jan 10 01:34:11 volumio volumio[8011]: info: Loading plugin "spop"... Jan 10 01:34:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.59.3 Jan 10 01:34:11 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.59.3 Jan 10 01:34:11 volumio avahi-daemon[664]: Withdrawing address record for 169.254.59.3 on eth0. Jan 10 01:34:11 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:11 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:12 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 01:34:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Jan 10 01:34:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:12 volumio go-librespot[8167]: go-librespot daemon starting... Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=debug msg="app state loaded" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:12 volumio volumio[8011]: info: Loading plugin "squeezelite_mc"... Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-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]" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-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]" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=info msg="zeroconf server listening on port 34919" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=debug msg="obtained new client token: AADbair4TkzDe/rFoQr2EBw2b8eapPA7c/4m1AQVs2K+DxCJVIbzWn92ylx95Ja3OE59K2FvNdpI9i0M4Ftrl6BRxZ7n1AgLM8GLVB72Kce6EmaoJgKSvPpj2oWBv0cOvu2jd+4D3pF/z+f3SPtQnlQnhMmJ5Gz7JknBJnWrp8gJrRC3/H7/t66Dck371zV5tF2IuSVFriEpc8aA0aqNoDOw8iX7iZI+M6ftK5Ki1eaxHyY18T24/N2zaQ==" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:12 volumio go-librespot[8168]: time="2026-01-10T01:34:12-06:00" level=debug msg="completed challenge" Jan 10 01:34:13 volumio go-librespot[8168]: time="2026-01-10T01:34: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 " Jan 10 01:34:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:13 volumio volumio[8011]: info: Loading plugin "youtube2"... Jan 10 01:34:14 volumio volumio[8011]: info: Loading plugin "ytcr"... Jan 10 01:34:14 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 01:34:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Jan 10 01:34:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:16 volumio go-librespot[8189]: go-librespot daemon starting... Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=debug msg="app state loaded" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:16 volumio volumio[8011]: info: Loading plugin "ytmusic"... Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=info msg="zeroconf server listening on port 42427" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=debug msg="obtained new client token: AADm3q6NIwlq0M94KUwEb6uewOtYZgXQoNSPepLRK5Dzw2eDNRrc+YrCPFRZb7TEf/gnxqBzOtM0+IgzTRL+ld6GDEz9JBOTbZLUTRnc8ZYtHEuGjRUSmDqg42WtTdjk7VoUGc+VT6Tfubg2cKG8/frrDvnt18wZr++A6jAwQK6i4q++X5uB6G9uLEvJs2yndU4M1GFTqPdhGoDs9RC9s1IjK2Lcz6puItyPHfBlOAvOOuIkK9e3kavv2g==" Jan 10 01:34:16 volumio go-librespot[8190]: time="2026-01-10T01:34:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:17 volumio go-librespot[8190]: time="2026-01-10T01:34:17-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:17 volumio go-librespot[8190]: time="2026-01-10T01:34:17-06:00" level=debug msg="completed challenge" Jan 10 01:34:17 volumio go-librespot[8190]: time="2026-01-10T01:34: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 " Jan 10 01:34:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:17 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.191.83 Jan 10 01:34:17 volumio avahi-daemon[664]: Registering new address record for 169.254.191.83 on eth0.IPv4. Jan 10 01:34:17 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:17 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.191.83 Jan 10 01:34:17 volumio volumio[8011]: info: Plugin now_playing is not enabled Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "outputs"... Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "albumart"... Jan 10 01:34:17 volumio volumio[8011]: info: Plugin example_plugin is not enabled Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "inputs"... Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "updater_comm"... Jan 10 01:34:17 volumio volumio[8011]: info: Plugin mpdemulation is not enabled Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "rest_api"... Jan 10 01:34:17 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.191.83 Jan 10 01:34:17 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.191.83 Jan 10 01:34:17 volumio avahi-daemon[664]: Withdrawing address record for 169.254.191.83 on eth0. Jan 10 01:34:17 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "websocket"... Jan 10 01:34:17 volumio volumio[8011]: info: Starting Socket.io Server version 1.7.4 Jan 10 01:34:17 volumio volumio[8011]: info: Plugin fusiondsp is not enabled Jan 10 01:34:17 volumio volumio[8011]: info: Plugin mpdoutput is not enabled Jan 10 01:34:17 volumio volumio[8011]: info: Plugin RoonBridge is not enabled Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "podcast"... Jan 10 01:34:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:17 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:17 volumio volumio[8011]: info: ControllerPodcast::constructor Jan 10 01:34:17 volumio volumio[8011]: info: Loading plugin "volusonic"... Jan 10 01:34:17 volumio volumio[8213]: Forking 3 albumart workers Jan 10 01:34:19 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:19] [connect] Successful connection Jan 10 01:34:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Jan 10 01:34:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:20 volumio volumio[8011]: info: Applying required configuration parameters for plugin volusonic Jan 10 01:34:20 volumio volumio[8011]: info: Loading plugin "backup_restore"... Jan 10 01:34:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:20 volumio go-librespot[8272]: go-librespot daemon starting... Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-06:00" level=debug msg="app state loaded" Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:20 volumio volumio[8240]: Starting albumart workers Jan 10 01:34:20 volumio volumio[8241]: Starting albumart workers Jan 10 01:34:20 volumio volumio[8011]: info: Applying required configuration parameters for plugin backup_restore Jan 10 01:34:20 volumio volumio[8239]: Starting albumart workers Jan 10 01:34:20 volumio volumio[8011]: info: Plugin rpi_eeprom_config is not enabled Jan 10 01:34:20 volumio volumio[8011]: info: Plugin rpi_eeprom_updater is not enabled Jan 10 01:34:20 volumio volumio[8011]: info: Loading plugin "scheduledrestart"... Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-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]" Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-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]" Jan 10 01:34:20 volumio go-librespot[8273]: time="2026-01-10T01:34:20-06:00" level=info msg="zeroconf server listening on port 42357" Jan 10 01:34:21 volumio go-librespot[8273]: time="2026-01-10T01:34:21-06:00" level=debug msg="obtained new client token: AABFocQlxhalNii63mVmF62vljd7Vza/5+5pXo/rFaKoVf+mj5DqwYJYgiSJbAJJ8HEwtQG2iTeQ5r45FLPt7FGtvwqxoUbSjXeYWKVUc1tjlrg4lS58efUsHC85ti/7n/SDEisuGlAmd6mQLWsJlh/CYtseZfM6evb0HW4IikXOPSLU67P6ALMNR2a4oHvGUkLmswUHAVp0A9i48t0+Kt7btnFhlu4p1WqoU25XUDxEczPI66BFwTk=" Jan 10 01:34:21 volumio go-librespot[8273]: time="2026-01-10T01:34:21-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:21 volumio go-librespot[8273]: time="2026-01-10T01:34:21-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:21 volumio go-librespot[8273]: time="2026-01-10T01:34:21-06:00" level=debug msg="completed challenge" Jan 10 01:34:21 volumio go-librespot[8273]: time="2026-01-10T01:34: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 " Jan 10 01:34:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:21 volumio volumio[8011]: info: Applying required configuration parameters for plugin scheduledrestart Jan 10 01:34:21 volumio volumio[8011]: info: Plugin Bluetoothremote is not enabled Jan 10 01:34:21 volumio volumio[8011]: info: Plugin music_services_shield is not enabled Jan 10 01:34:21 volumio volumio[8011]: info: Loading plugin "Systeminfo"... Jan 10 01:34:21 volumio volumio[8011]: info: Plugin peppymeterbasic is not enabled Jan 10 01:34:21 volumio volumio[8011]: info: Loading plugin "peppyspectrum"... Jan 10 01:34:22 volumio volumio[8011]: info: Loading i18n strings for locale en Jan 10 01:34:22 volumio volumio[8011]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 01:34:22 volumio volumio[8011]: Updating browse sources language Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::initPlayerControls Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: Express server listening on port 3000 Jan 10 01:34:22 volumio volumio[8011]: [Metrics] WebUI: 19s 179.60ms Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::resetVolumioState Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::getcurrentVolume Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:22 volumio sudo[8303]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 01:34:22 volumio sudo[8303]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:22 volumio sudo[8303]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:22 volumio sudo[8305]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 01:34:22 volumio sudo[8305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:22 volumio sudo[8305]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:22 volumio volumio[8011]: info: Volumio Network Manager: Network status updated: 1 Jan 10 01:34:22 volumio volumio[8011]: info: VolumeController:: Volume=100 Mute =false Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::pushState Jan 10 01:34:22 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::updateTrackBlock Jan 10 01:34:22 volumio volumio[8011]: info: CorePlayQueue::getTrackBlock Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 01:34:22 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:22] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768030459 101 Jan 10 01:34:22 volumio volumio[8011]: 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 Jan 10 01:34:22 volumio volumio[8011]: info: Reloading queue from file Jan 10 01:34:22 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.202.80 Jan 10 01:34:22 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:22 volumio avahi-daemon[664]: Registering new address record for 169.254.202.80 on eth0.IPv4. Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::setRepeat null single undefined Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::pushState Jan 10 01:34:22 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::setRandom null Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::pushState Jan 10 01:34:22 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:22 volumio volumio[8011]: info: Setting Device type: Raspberry PI Jan 10 01:34:22 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:22 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:22 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:22 volumio volumio[8011]: info: VolumeController:: Volume=100 Mute =false Jan 10 01:34:22 volumio volumio[8011]: info: CoreStateMachine::pushState Jan 10 01:34:22 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:22 volumio volumio[8011]: info: Completed loading Core Plugins Jan 10 01:34:22 volumio volumio[8011]: info: Preparing to generate the ALSA configuration file Jan 10 01:34:22 volumio sudo[8335]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 01:34:22 volumio sudo[8335]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:22 volumio volumio[8011]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 01:34:22 volumio volumio[8011]: info: Discovery: Found device Volumio Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioGetState Jan 10 01:34:22 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:22 volumio volumio[8011]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 01:34:22 volumio volumio[8011]: info: Discovery: Found device Volumio Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::volumioGetState Jan 10 01:34:22 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:22 volumio sudo[8335]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:22 volumio volumio[8011]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 01:34:22 volumio volumio[8011]: info: Reading ALSA contributions from plugins. Jan 10 01:34:22 volumio volumio[8011]: info: Upmpdcli Daemon Started Jan 10 01:34:22 volumio volumio[8011]: info: Asound.conf file unchanged, so no further update is needed Jan 10 01:34:22 volumio volumio[8011]: info: Output device has changed, restarting MPD Jan 10 01:34:22 volumio volumio[8011]: info: Output device has changed, restarting Shairport Sync Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:22 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:22 volumio sudo[8338]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 01:34:22 volumio sudo[8338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:22 volumio sudo[8338]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:23 volumio sudo[8340]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 01:34:23 volumio sudo[8340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:23 volumio volumio[8011]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:23 volumio volumio[8011]: info: ___________ START PLUGINS ___________ Jan 10 01:34:23 volumio volumio[8011]: info: ControllerMpd::onStart: Initializing MPD Jan 10 01:34:23 volumio volumio[8011]: info: Creating MPD Configuration file Jan 10 01:34:23 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463056] CoreMusicLibrary::Adding element Media Servers Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio sudo[8350]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 01:34:23 volumio sudo[8350]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:23 volumio sudo[8348]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 01:34:23 volumio sudo[8348]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:23 volumio sudo[8348]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:23 volumio volumio[8011]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:23 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 01:34:23 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 01:34:23 volumio systemd[1]: mpd.service: Consumed 5.575s CPU time. Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:23 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 01:34:23 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 01:34:23 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 01:34:23 volumio volumio[8011]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463194] CoreMusicLibrary::Adding element Last_100 Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463199] CoreMusicLibrary::Adding element Webradio Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:34:23 volumio volumio[8011]: info: Initializing BBC Radios Jan 10 01:34:23 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 01:34:23 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463286] CoreMusicLibrary::Adding element Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463299] CoreMusicLibrary::Adding element SoundCloud Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.202.80 Jan 10 01:34:23 volumio volumio[8011]: info: Creating Spotify config file Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:23 volumio sudo[8367]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 01:34:23 volumio sudo[8367]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 01:34:23 volumio sudo[8367]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:23 volumio volumio[8011]: info: [squeezelite_mc] Starting proxy server... Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463666] CoreMusicLibrary::Adding element YouTube2 Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube2 Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463685] CoreMusicLibrary::Adding element YouTube Music Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube2 Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube Music Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463696] CoreMusicLibrary::Adding element Podcast Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube2 Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube Music Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Podcast Jan 10 01:34:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.202.80 Jan 10 01:34:23 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.202.80 Jan 10 01:34:23 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:23 volumio volumio[8011]: info: Loading i18n strings for locale en Jan 10 01:34:23 volumio avahi-daemon[664]: Withdrawing address record for 169.254.202.80 on eth0. Jan 10 01:34:23 volumio volumio[8011]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 01:34:23 volumio volumio[8011]: Updating browse sources language Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube2 Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube Music Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Podcast Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube2 Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube Music Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Podcast Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:23 volumio volumio[8011]: info: [1768030463752] CoreMusicLibrary::Adding element Volusonic Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube2 Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source YouTube Music Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Podcast Jan 10 01:34:23 volumio volumio[8011]: Cannot find translation for source Volusonic Jan 10 01:34:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:23 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:23 volumio volumio[8011]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 10 01:34:23 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 10 01:34:23 volumio volumio[8011]: info: Volumio Calling Home Jan 10 01:34:23 volumio volumio[8011]: info: [squeezelite_mc] Proxy server started on port 45747 Jan 10 01:34:23 volumio volumio[8011]: info: Preparing to generate the ALSA configuration file Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 01:34:24 volumio volumio[8011]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 01:34:24 volumio volumio[8011]: info: Reading ALSA contributions from plugins. Jan 10 01:34:24 volumio volumio[8011]: info: MPD Permissions set Jan 10 01:34:24 volumio volumio[8011]: info: MPD Permissions set Jan 10 01:34:24 volumio volumio[8011]: info: Spotify config file written Jan 10 01:34:24 volumio sudo[8400]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 01:34:24 volumio sudo[8400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:24 volumio volumio[8011]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 01:34:24 volumio volumio[8011]: info: VolumeController:: Volume=100 Mute =false Jan 10 01:34:24 volumio volumio[8011]: info: CoreStateMachine::pushState Jan 10 01:34:24 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:24 volumio volumio[8011]: info: [squeezelite_mc] Server discovery started Jan 10 01:34:24 volumio volumio[8011]: info: [squeezelite_mc] Player finder started Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 10 01:34:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: No need to fix Spotify hosts Jan 10 01:34:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:24 volumio go-librespot[8404]: go-librespot daemon starting... Jan 10 01:34:24 volumio sudo[8400]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="app state loaded" Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:24 volumio volumio[8011]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 10 01:34:24 volumio volumio[8011]: info: Volumio called home Jan 10 01:34:24 volumio volumio[8011]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 10 01:34:24 volumio volumio[8011]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 10 01:34:24 volumio volumio[8011]: 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 Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=info msg="zeroconf server listening on port 45467" Jan 10 01:34:24 volumio volumio[8011]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 01:34:24 volumio volumio[8011]: SPOTIFY: BQBcCGaNGlppQhsjIfY1dblQiB_kfU-xsEUXZZli5oAoTXTYKeMQDDE64F5giIWjq4b7pFppS0oXwUZfhDyA9_r2UUKOcG0HE-ZM_Fl2Jqwsq5Cmj9lhd-q33Vz9FYEsbwWyGGoQP--qe_y--LDOLdcc8wZFHoYiC27vDr856Mysn4A4YyA3fCt_xvBc5eXLA2fhIf-7uOtiJONIcxZRGqJqPiQ9jiYS08DZYYw Jan 10 01:34:24 volumio volumio[8011]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 01:34:24 volumio volumio[8011]: info: New Spotify access token = BQBcCGaNGlppQhsjIfY1dblQiB_kfU-xsEUXZZli5oAoTXTYKeMQDDE64F5giIWjq4b7pFppS0oXwUZfhDyA9_r2UUKOcG0HE-ZM_Fl2Jqwsq5Cmj9lhd-q33Vz9FYEsbwWyGGoQP--qe_y--LDOLdcc8wZFHoYiC27vDr856Mysn4A4YyA3fCt_xvBc5eXLA2fhIf-7uOtiJONIcxZRGqJqPiQ9jiYS08DZYYw Jan 10 01:34:24 volumio volumio[8011]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 10 01:34:24 volumio volumio[8011]: info: Starting Shairport Sync Jan 10 01:34:24 volumio volumio[8011]: info: Starting Shairport Sync Jan 10 01:34:24 volumio volumio[8011]: info: Starting Shairport Sync Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="obtained new client token: AAAv8jkZAT5rPkDMlIW78DcCL8T/tHCtA54O8Jyrpeqq/RQlsNbdx9SHLPFuymeOmo63JemdHdU3Ltrd9zR8pROGPm5RowhW1jc09DIo0hEzMpmH1iV0jWOdPMFdGDC9S2+Pm4Fttz3IXgkScMamEZT1LCsBrlPsWWDm54PlDbibIhsFqSTcHNkx1lrPvTBb4kinm+sK1qRxtWQMKK52hEI6UymgILUvL8y6Gz5cIPIMRLpYIF8kFajSsg==" Jan 10 01:34:24 volumio sudo[8427]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:24 volumio sudo[8427]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:24 volumio sudo[8425]: 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 Jan 10 01:34:24 volumio sudo[8425]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:24 volumio sudo[8425]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:24 volumio sudo[8430]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:24 volumio sudo[8430]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:24 volumio sudo[8432]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:24 volumio sudo[8432]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:24 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 01:34:24 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 01:34:24 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 01:34:24 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:24 volumio systemd[1]: shairport-sync.service: Consumed 1.964s CPU time. Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34:24-06:00" level=debug msg="completed challenge" Jan 10 01:34:24 volumio volumio[8011]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 10 01:34:24 volumio volumio[8011]: info: Asound.conf file unchanged, so no further update is needed Jan 10 01:34:24 volumio volumio[8011]: info: Output device has changed, restarting MPD Jan 10 01:34:24 volumio go-librespot[8415]: time="2026-01-10T01:34: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 " Jan 10 01:34:24 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:24 volumio sudo[8427]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:24 volumio volumio[8011]: info: Output device has changed, restarting Shairport Sync Jan 10 01:34:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:24 volumio sudo[8440]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:24 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:24 volumio sudo[8440]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:24 volumio sudo[8444]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 01:34:24 volumio sudo[8444]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:24 volumio sudo[8440]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:24 volumio sudo[8442]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 01:34:24 volumio sudo[8442]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:25 volumio sudo[8442]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:25 volumio volumio[8011]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 01:34:25 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 01:34:25 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 01:34:25 volumio systemd[1]: mpd.service: Consumed 1.663s CPU time. Jan 10 01:34:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 01:34:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:25 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 01:34:25 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 01:34:25 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 01:34:25 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 01:34:25 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 01:34:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:25 volumio sudo[8432]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:25 volumio volumio[8011]: info: MPD Permissions set Jan 10 01:34:25 volumio volumio[8011]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 01:34:25 volumio sudo[8430]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:25 volumio volumio[8011]: info: Shairport-Sync Started Jan 10 01:34:25 volumio volumio[8011]: Error adding Membership: Error: addMembership EINVAL Jan 10 01:34:25 volumio volumio[8011]: info: Shairport-Sync Started Jan 10 01:34:25 volumio volumio[8011]: info: Shairport-Sync Started Jan 10 01:34:25 volumio sudo[8473]: 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 Jan 10 01:34:25 volumio sudo[8473]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio sudo[8473]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::volumioGetState Jan 10 01:34:25 volumio volumio[8011]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:25 volumio sudo[8469]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 01:34:25 volumio sudo[8469]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 01:34:25 volumio volumio[8011]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 10 01:34:25 volumio sudo[8469]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:25 volumio sudo[8496]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 10 01:34:25 volumio sudo[8496]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:25 volumio volumio[8011]: info: Starting Shairport Sync Jan 10 01:34:25 volumio sudo[8500]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:25 volumio sudo[8500]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:25 volumio volumio[8011]: 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"} Jan 10 01:34:25 volumio volumio[8011]: info: Spotify Successfully logged in Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:25 volumio systemd[1]: Reloading. Jan 10 01:34:25 volumio volumio[8011]: info: [1768030465591] CoreMusicLibrary::Adding element Spotify Jan 10 01:34:25 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:25 volumio volumio[8011]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:25 volumio volumio[8011]: Cannot find translation for source SoundCloud Jan 10 01:34:25 volumio volumio[8011]: Cannot find translation for source YouTube2 Jan 10 01:34:25 volumio volumio[8011]: Cannot find translation for source YouTube Music Jan 10 01:34:25 volumio volumio[8011]: Cannot find translation for source Podcast Jan 10 01:34:25 volumio volumio[8011]: Cannot find translation for source Volusonic Jan 10 01:34:25 volumio volumio[8011]: Cannot find translation for source Spotify Jan 10 01:34:26 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:26 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:26 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:26 volumio volumio[8011]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:26 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 01:34:27 volumio volumio[8011]: info: go-librespot daemon successfully initialized Jan 10 01:34:28 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. Jan 10 01:34:28 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. Jan 10 01:34:28 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.22.178 Jan 10 01:34:28 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:28 volumio avahi-daemon[664]: Registering new address record for 169.254.22.178 on eth0.IPv4. Jan 10 01:34:28 volumio volumio[8011]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 01:34:28 volumio volumio[8011]: Error: addMembership ENODEV Jan 10 01:34:28 volumio volumio[8011]: at Socket.addMembership (node:dgram:860:11) Jan 10 01:34:28 volumio volumio[8011]: at addMembership (/volumio/node_modules/node-ssdp/lib/index.js:264:16) { Jan 10 01:34:28 volumio volumio[8011]: errno: -19, Jan 10 01:34:28 volumio volumio[8011]: code: 'ENODEV', Jan 10 01:34:28 volumio volumio[8011]: syscall: 'addMembership' Jan 10 01:34:28 volumio volumio[8011]: } Jan 10 01:34:28 volumio volumio[8011]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 01:34:29 volumio sudo[8496]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Jan 10 01:34:29 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:29 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:29 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:29 volumio go-librespot[8560]: go-librespot daemon starting... Jan 10 01:34:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 01:34:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 01:34:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:29 volumio systemd[1]: shairport-sync.service: Consumed 1.444s CPU time. Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="app state loaded" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:29 volumio sudo[8500]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:29 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.22.178 Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=info msg="zeroconf server listening on port 46599" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="obtained new client token: AAAErccBEi0AryPQ1CPrB9h/Cb2p42p+gVjRqwyKmIGcFvllAWVXWv7S5Kvzvnjgu4PkA2zY/IhJJrx0pX23gyKhKEN7UJVvRWJpnfdyz8yoaCIS53NGAqXF7NRXoyHh/TJQWuFxWCTaDxkIqJMUCzdjCyUAtNVsculDHZrAOZA4jIPTv1+aCiphiXaH7ZrRcUVuMfqWjDV89+SDIUtdVK8qgo9hPSwYffYdR5Qh4mcFg4wxti9xjs9J9w==" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34:29-06:00" level=debug msg="completed challenge" Jan 10 01:34:29 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.22.178 Jan 10 01:34:29 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.22.178 Jan 10 01:34:29 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:29 volumio avahi-daemon[664]: Withdrawing address record for 169.254.22.178 on eth0. Jan 10 01:34:29 volumio go-librespot[8562]: time="2026-01-10T01:34: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 " Jan 10 01:34:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:29 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:29 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:29 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:29 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:30 volumio sudo[8603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 01:33' Jan 10 01:34:30 volumio sudo[8603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:30 volumio sudo[8603]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:30 volumio mpd[8497]: 2026-01-10T01:34:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 01:34:30 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 01:34:30 volumio sudo[8340]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:30 volumio sudo[8350]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:30 volumio sudo[8444]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:31 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 01:34:31 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:31] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 01:34:31 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:31] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 01:34:31 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:31 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 01:34:31 volumio systemd[1]: volumio.service: Consumed 43.662s CPU time. Jan 10 01:34:31 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 01:34:31 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 01:34:31 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 17358. Jan 10 01:34:31 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 01:34:31 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 01:34:31 volumio systemd[1]: volumio.service: Consumed 43.662s CPU time. Jan 10 01:34:31 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 01:34:31 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 01:34:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33. Jan 10 01:34:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:33 volumio go-librespot[8640]: go-librespot daemon starting... Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="app state loaded" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=info msg="zeroconf server listening on port 40145" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="obtained new client token: AACzwDSN2KqNDi29QV5QSrl7B7aY3LgmK9M+bOIysbrxz/yWN8qRyVcYy/udABnt8IwvJP35l8VziLYuRw5XNGZy5K8iTRFxQ8aDCb7ZPShQFQZC17YY+LJQ6dUfHhrl6vxtwFvDcS5HIRZasTUjuY/qM9AEMaT4zuX+/OQ2/K65oC2c7+Uwf4Zif0X6pn/MRwlG/MvK3mKumagDv6WVuf64x3Ao7R/nsnWewo62QrT9AzeCSR/acFA2bw==" Jan 10 01:34:33 volumio volumio[8625]: info: ------------------------------------------- Jan 10 01:34:33 volumio volumio[8625]: info: ----- Volumio3 ---- Jan 10 01:34:33 volumio volumio[8625]: info: ------------------------------------------- Jan 10 01:34:33 volumio volumio[8625]: info: ----- System startup ---- Jan 10 01:34:33 volumio volumio[8625]: info: ------------------------------------------- Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=debug msg="completed challenge" Jan 10 01:34:33 volumio go-librespot[8641]: time="2026-01-10T01:34:33-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:34:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:34 volumio volumio[8625]: info: MYVOLUMIO Environment detected Jan 10 01:34:34 volumio volumio[8625]: info: Plugin folders cleanup Jan 10 01:34:34 volumio volumio[8625]: info: Scanning into folder /volumio/app/plugins/ Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category audio_interface Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category miscellanea Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category music_service Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category plugins.json Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category system_controller Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category user_interface Jan 10 01:34:34 volumio volumio[8625]: info: Scanning into folder /data/plugins/ Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category audio_interface Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category music_service Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category system_controller Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category system_hardware Jan 10 01:34:34 volumio volumio[8625]: info: Scanning category user_interface Jan 10 01:34:34 volumio volumio[8625]: info: Plugin folders cleanup completed Jan 10 01:34:34 volumio volumio[8625]: info: ------------------------------------------- Jan 10 01:34:34 volumio volumio[8625]: info: ----- Core plugins startup ---- Jan 10 01:34:34 volumio volumio[8625]: info: ------------------------------------------- Jan 10 01:34:34 volumio volumio[8625]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 01:34:34 volumio volumio[8625]: info: Adding plugin upnp to MyMusic Plugins Jan 10 01:34:34 volumio volumio[8625]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 01:34:34 volumio volumio[8625]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 01:34:34 volumio volumio[8625]: info: Loading plugins from folder /data/plugins/ Jan 10 01:34:34 volumio volumio[8625]: info: Loading plugin "system"... Jan 10 01:34:34 volumio volumio[8625]: info: Loading plugin "appearance"... Jan 10 01:34:35 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.61.126 Jan 10 01:34:35 volumio avahi-daemon[664]: Registering new address record for 169.254.61.126 on eth0.IPv4. Jan 10 01:34:35 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:35 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:35 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:35 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:35 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.61.126 Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "network"... Jan 10 01:34:35 volumio volumio[8625]: info: Refreshing Cached IP Addresses Jan 10 01:34:35 volumio sudo[8679]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 01:34:35 volumio sudo[8679]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:35 volumio sudo[8681]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 01:34:35 volumio sudo[8681]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:35 volumio sudo[8679]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "services"... Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "alsa_controller"... Jan 10 01:34:35 volumio sudo[8681]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:35 volumio sudo[8689]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 01:34:35 volumio sudo[8689]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:35 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "wizard"... Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "networkfs"... Jan 10 01:34:35 volumio volumio[8625]: info: Starting Udev Watcher for removable devices Jan 10 01:34:35 volumio volumio[8625]: info: Ignoring mount for partition: boot Jan 10 01:34:35 volumio volumio[8625]: info: Ignoring mount for partition: volumio Jan 10 01:34:35 volumio volumio[8625]: info: Ignoring mount for partition: volumio_data Jan 10 01:34:35 volumio volumio[8625]: info: Mounting Device Wikipedia Jan 10 01:34:35 volumio sudo[8718]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Jan 10 01:34:35 volumio sudo[8718]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:35 volumio sudo[8718]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:35 volumio volumio[8625]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 01:34:35 volumio volumio[8625]: dmesg(1) may have more information after failed mount system call. Jan 10 01:34:35 volumio volumio[8625]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Jan 10 01:34:35 volumio volumio[8625]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Jan 10 01:34:35 volumio volumio[8625]: dmesg(1) may have more information after failed mount system call. Jan 10 01:34:35 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "volumio_command_line_client"... Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "upnp"... Jan 10 01:34:35 volumio volumio[8625]: info: [1768030475868] Starting Upmpd Daemon Jan 10 01:34:35 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "my_music"... Jan 10 01:34:35 volumio volumio[8625]: info: Loading plugin "mpd"... Jan 10 01:34:36 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.61.126 Jan 10 01:34:36 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.61.126 Jan 10 01:34:36 volumio avahi-daemon[664]: Withdrawing address record for 169.254.61.126 on eth0. Jan 10 01:34:36 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:36 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:36 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:36 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:36 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:36 volumio sudo[8689]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:36 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:36] [connect] Successful connection Jan 10 01:34:36 volumio volumio[8625]: info: Loading plugin "upnp_browser"... Jan 10 01:34:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. Jan 10 01:34:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:36 volumio go-librespot[8736]: go-librespot daemon starting... Jan 10 01:34:36 volumio go-librespot[8737]: time="2026-01-10T01:34:36-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:36 volumio go-librespot[8737]: time="2026-01-10T01:34:36-06:00" level=debug msg="app state loaded" Jan 10 01:34:36 volumio go-librespot[8737]: time="2026-01-10T01:34:36-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:36 volumio go-librespot[8737]: time="2026-01-10T01:34:36-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-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]" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-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]" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-06:00" level=info msg="zeroconf server listening on port 37489" Jan 10 01:34:37 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-06:00" level=debug msg="obtained new client token: AADqIj2Z7M1EBpokQclZx1mWPhluRMfliLqaEVpScgJDsyV3y/8ItMoh3fzRnvXLgvoalt9x1aoKvjSiujPnyGONLLcg8YoCpS9qhYUHVnnJIe6yu4u8H2+ugDeEjsVTl3KfjPs3Sx/RmBtvk9O6x6Yvfr4xtTvqqXLKAqJRqL6sf5CPHT3ATMfETca5Fccim5585sdvVRDJGfZNdxw3v53YGZOKj2TEWD8sQwbxdLAKiyXZwvyql2HHaA==" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-06:00" level=debug msg="completed challenge" Jan 10 01:34:37 volumio go-librespot[8737]: time="2026-01-10T01:34:37-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 " Jan 10 01:34:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:39 volumio volumio[8625]: info: Loading plugin "alarm-clock"... Jan 10 01:34:39 volumio volumio[8625]: info: Loading plugin "airplay_emulation"... Jan 10 01:34:39 volumio volumio[8625]: info: Starting Shairport Sync Jan 10 01:34:39 volumio volumio[8625]: info: Loading plugin "last_100"... Jan 10 01:34:39 volumio volumio[8625]: info: Loading plugin "webradio"... Jan 10 01:34:39 volumio volumio[8625]: info: Loading plugin "i2s_dacs"... Jan 10 01:34:39 volumio volumio[8625]: info: I2S DAC not set, start Auto-detection Jan 10 01:34:39 volumio volumio[8625]: info: Loading plugin "volumiodiscovery"... Jan 10 01:34:39 volumio volumio[8625]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:39 volumio volumio[8625]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:39 volumio volumio[8625]: *** WARNING *** For more information see Jan 10 01:34:39 volumio volumio[8625]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:39 volumio volumio[8625]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:39 volumio volumio[8625]: *** WARNING *** For more information see Jan 10 01:34:39 volumio node[8625]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:39 volumio node[8625]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:39 volumio node[8625]: *** WARNING *** For more information see Jan 10 01:34:39 volumio node[8625]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 01:34:39 volumio node[8625]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 01:34:39 volumio node[8625]: *** WARNING *** For more information see Jan 10 01:34:39 volumio volumio[8625]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 01:34:39 volumio volumio[8625]: info: Discovery: Started advertising with name: Volumio Jan 10 01:34:39 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 01:34:39 volumio volumio[8625]: info: Loading plugin "bandcamp"... Jan 10 01:34:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Jan 10 01:34:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:40 volumio go-librespot[8751]: go-librespot daemon starting... Jan 10 01:34:40 volumio go-librespot[8752]: time="2026-01-10T01:34:40-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:40 volumio go-librespot[8752]: time="2026-01-10T01:34:40-06:00" level=debug msg="app state loaded" Jan 10 01:34:40 volumio go-librespot[8752]: time="2026-01-10T01:34:40-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:40 volumio go-librespot[8752]: time="2026-01-10T01:34:40-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:40 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.85.112 Jan 10 01:34:40 volumio avahi-daemon[664]: Registering new address record for 169.254.85.112 on eth0.IPv4. Jan 10 01:34:40 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:40 volumio volumio[8625]: info: Plugin calmradio is not enabled Jan 10 01:34:40 volumio volumio[8625]: info: Loading plugin "soundcloud"... Jan 10 01:34:40 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:40 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:40 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-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]" Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-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]" Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-06:00" level=info msg="zeroconf server listening on port 42093" Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-06:00" level=debug msg="obtained new client token: AAB/bxgh/OyfsDGiaSRzBlapqj6nt7hTTb9BFqto0e9R28Gtg2ZH97C59iubRJAfUAGU5A4L6f9rpDOYnRzWIdpZeQjH893ZaGDrA69Sy85qI/mH4dg7euHpSbqdq+Y4Bx7zZ/k8nAogAxqmeFjKvjB/8ExUJtOA391O8oBesQNSmkyqcvWzzZzjOgQ6inAfTusxRQ0/rxgeKz5K7xnoxOWv91LhkKi64kKg4+m8hxgtl1fI1v+uv9E=" Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-06:00" level=debug msg="completed challenge" Jan 10 01:34:41 volumio volumio[8625]: info: Loading plugin "spop"... Jan 10 01:34:41 volumio go-librespot[8752]: time="2026-01-10T01:34:41-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:34:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:41 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.85.112 Jan 10 01:34:41 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 01:34:41 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.85.112 Jan 10 01:34:41 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.85.112 Jan 10 01:34:41 volumio avahi-daemon[664]: Withdrawing address record for 169.254.85.112 on eth0. Jan 10 01:34:41 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:41 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:41 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:41 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:41 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:42 volumio volumio[8625]: info: Loading plugin "squeezelite_mc"... Jan 10 01:34:42 volumio volumio[8625]: info: Loading plugin "youtube2"... Jan 10 01:34:43 volumio volumio[8625]: info: Loading plugin "ytcr"... Jan 10 01:34:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Jan 10 01:34:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:44 volumio go-librespot[8794]: go-librespot daemon starting... Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=debug msg="app state loaded" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-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]" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-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]" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=info msg="zeroconf server listening on port 39099" Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=debug msg="obtained new client token: AAC0wGaHg44RCQVcVaiornX77DeKbRIfyKM23pAWpdvSvqLIfQug54Gim7qbkOPQ5pQPTSuHXk2a8BzLOQWN45qY/b2daQ8MysxnrR5XkBT8LMOWBstNTu28iQHbK9RQ+tJZkweFqh/FUMUNdTMIRvIssl1vDj+j/S3L44+CHc3oYwAcT47tCV1r7gxEI65vBnYTMb9sEI0NLjT2Az4bjD1ZlV6QWwb9s1y9kX0/W03zRFIMc23evm0xOQ==" Jan 10 01:34:44 volumio volumio[8625]: info: Loading plugin "ytmusic"... Jan 10 01:34:44 volumio go-librespot[8795]: time="2026-01-10T01:34:44-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:45 volumio go-librespot[8795]: time="2026-01-10T01:34:45-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:45 volumio go-librespot[8795]: time="2026-01-10T01:34:45-06:00" level=debug msg="completed challenge" Jan 10 01:34:45 volumio go-librespot[8795]: time="2026-01-10T01:34:45-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:34:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:45 volumio volumio[8625]: info: Plugin now_playing is not enabled Jan 10 01:34:45 volumio volumio[8625]: info: Loading plugin "outputs"... Jan 10 01:34:45 volumio volumio[8625]: info: Loading plugin "albumart"... Jan 10 01:34:45 volumio volumio[8625]: info: Plugin example_plugin is not enabled Jan 10 01:34:45 volumio volumio[8625]: info: Loading plugin "inputs"... Jan 10 01:34:45 volumio volumio[8625]: info: Loading plugin "updater_comm"... Jan 10 01:34:45 volumio volumio[8625]: info: Plugin mpdemulation is not enabled Jan 10 01:34:45 volumio volumio[8625]: info: Loading plugin "rest_api"... Jan 10 01:34:45 volumio volumio[8625]: info: Loading plugin "websocket"... Jan 10 01:34:45 volumio volumio[8625]: info: Starting Socket.io Server version 1.7.4 Jan 10 01:34:45 volumio volumio[8625]: info: Plugin fusiondsp is not enabled Jan 10 01:34:45 volumio volumio[8625]: info: Plugin mpdoutput is not enabled Jan 10 01:34:45 volumio volumio[8625]: info: Plugin RoonBridge is not enabled Jan 10 01:34:45 volumio volumio[8625]: info: Loading plugin "podcast"... Jan 10 01:34:45 volumio volumio[8625]: info: ControllerPodcast::constructor Jan 10 01:34:46 volumio volumio[8625]: info: Loading plugin "volusonic"... Jan 10 01:34:46 volumio volumio[8802]: Forking 3 albumart workers Jan 10 01:34:46 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.65.162 Jan 10 01:34:46 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:46 volumio avahi-daemon[664]: Registering new address record for 169.254.65.162 on eth0.IPv4. Jan 10 01:34:46 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:46 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:46 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:47 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.65.162 Jan 10 01:34:47 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 01:34:47 volumio volumio[8625]: info: Applying required configuration parameters for plugin volusonic Jan 10 01:34:47 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.65.162 Jan 10 01:34:47 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.65.162 Jan 10 01:34:47 volumio avahi-daemon[664]: Withdrawing address record for 169.254.65.162 on eth0. Jan 10 01:34:47 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:47 volumio volumio[8625]: info: Loading plugin "backup_restore"... Jan 10 01:34:47 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:47 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:47 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:47 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:48 volumio volumio[8827]: Starting albumart workers Jan 10 01:34:48 volumio volumio[8828]: Starting albumart workers Jan 10 01:34:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37. Jan 10 01:34:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:48 volumio volumio[8826]: Starting albumart workers Jan 10 01:34:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:48 volumio go-librespot[8889]: go-librespot daemon starting... Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=debug msg="app state loaded" Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:48 volumio volumio[8625]: info: Applying required configuration parameters for plugin backup_restore Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:48 volumio volumio[8625]: info: Plugin rpi_eeprom_config is not enabled Jan 10 01:34:48 volumio volumio[8625]: info: Plugin rpi_eeprom_updater is not enabled Jan 10 01:34:48 volumio volumio[8625]: info: Loading plugin "scheduledrestart"... Jan 10 01:34:48 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:48] [connect] Successful connection Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:34:48 volumio go-librespot[8890]: time="2026-01-10T01:34:48-06:00" level=info msg="zeroconf server listening on port 38671" Jan 10 01:34:48 volumio volumio[8625]: info: Applying required configuration parameters for plugin scheduledrestart Jan 10 01:34:49 volumio volumio[8625]: info: Plugin Bluetoothremote is not enabled Jan 10 01:34:49 volumio volumio[8625]: info: Plugin music_services_shield is not enabled Jan 10 01:34:49 volumio volumio[8625]: info: Loading plugin "Systeminfo"... Jan 10 01:34:49 volumio go-librespot[8890]: time="2026-01-10T01:34:49-06:00" level=debug msg="obtained new client token: AADpfui5Szh7uuAUwuXd0Is03RcaEzTfp+W9rXvq/XgQHJgQ1O1lQlNIbyrKa977QJDN80mEJ5bMgH7lifnxsoMcVVuroWYVrr+/u9ySmvIoPyCv4Xgqs4+WuVj7uQSHa1syKFsTvdsO3WlGUzSQKSBzw8xPctx0XUangopnQIZ1dlgJB5nk3DVePgKUbBq+Y1/vbWtNRwjCkcfpz8uL97KlUBvl5RYLhOp8CRwUQRtBYkxhOujvVNQ=" Jan 10 01:34:49 volumio go-librespot[8890]: time="2026-01-10T01:34:49-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:49 volumio go-librespot[8890]: time="2026-01-10T01:34:49-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:49 volumio go-librespot[8890]: time="2026-01-10T01:34:49-06:00" level=debug msg="completed challenge" Jan 10 01:34:49 volumio go-librespot[8890]: time="2026-01-10T01:34:49-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:34:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:49 volumio volumio[8625]: info: Plugin peppymeterbasic is not enabled Jan 10 01:34:49 volumio volumio[8625]: info: Loading plugin "peppyspectrum"... Jan 10 01:34:50 volumio volumio[8625]: info: Loading i18n strings for locale en Jan 10 01:34:50 volumio volumio[8625]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 01:34:50 volumio volumio[8625]: Updating browse sources language Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::initPlayerControls Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:50 volumio volumio[8625]: Express server listening on port 3000 Jan 10 01:34:50 volumio volumio[8625]: [Metrics] WebUI: 17s 674.53ms Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::resetVolumioState Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::getcurrentVolume Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:50 volumio sudo[8920]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 01:34:50 volumio sudo[8920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:50 volumio sudo[8920]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:50 volumio sudo[8922]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 01:34:50 volumio sudo[8922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:50 volumio sudo[8922]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:50 volumio volumio[8625]: info: Volumio Network Manager: Network status updated: 1 Jan 10 01:34:50 volumio volumio[8625]: info: VolumeController:: Volume=100 Mute =false Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::pushState Jan 10 01:34:50 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::updateTrackBlock Jan 10 01:34:50 volumio volumio[8625]: info: CorePlayQueue::getTrackBlock Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 01:34:50 volumio volumio-remote-updater[14193]: [2026-01-10 01:34:50] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768030488 101 Jan 10 01:34:50 volumio volumio[8625]: 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 Jan 10 01:34:50 volumio volumio[8625]: info: Reloading queue from file Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::setRepeat null single undefined Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::pushState Jan 10 01:34:50 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::setRandom null Jan 10 01:34:50 volumio volumio[8625]: info: CoreStateMachine::pushState Jan 10 01:34:50 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:50 volumio volumio[8625]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:50 volumio volumio[8625]: info: Setting Device type: Raspberry PI Jan 10 01:34:51 volumio volumio[8625]: info: VolumeController:: Volume=100 Mute =false Jan 10 01:34:51 volumio volumio[8625]: info: CoreStateMachine::pushState Jan 10 01:34:51 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:51 volumio volumio[8625]: info: Completed loading Core Plugins Jan 10 01:34:51 volumio volumio[8625]: info: Preparing to generate the ALSA configuration file Jan 10 01:34:51 volumio sudo[8935]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 01:34:51 volumio sudo[8935]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:51 volumio volumio[8625]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 01:34:51 volumio volumio[8625]: info: Discovery: Found device Volumio Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioGetState Jan 10 01:34:51 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:51 volumio volumio[8625]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Jan 10 01:34:51 volumio volumio[8625]: info: Discovery: Found device Volumio Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioGetState Jan 10 01:34:51 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:51 volumio volumio[8625]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 01:34:51 volumio volumio[8625]: info: Reading ALSA contributions from plugins. Jan 10 01:34:51 volumio sudo[8935]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:51 volumio volumio[8625]: info: Upmpdcli Daemon Started Jan 10 01:34:51 volumio volumio[8625]: info: Asound.conf file unchanged, so no further update is needed Jan 10 01:34:51 volumio volumio[8625]: info: Output device has changed, restarting MPD Jan 10 01:34:51 volumio volumio[8625]: info: Output device has changed, restarting Shairport Sync Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:51 volumio sudo[8938]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 01:34:51 volumio sudo[8938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:51 volumio sudo[8940]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 01:34:51 volumio sudo[8940]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:51 volumio sudo[8938]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:51 volumio volumio[8625]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:51 volumio volumio[8625]: info: ___________ START PLUGINS ___________ Jan 10 01:34:51 volumio volumio[8625]: info: ControllerMpd::onStart: Initializing MPD Jan 10 01:34:51 volumio volumio[8625]: info: Creating MPD Configuration file Jan 10 01:34:51 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491215] CoreMusicLibrary::Adding element Media Servers Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio sudo[8950]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 01:34:51 volumio sudo[8950]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:51 volumio sudo[8948]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 01:34:51 volumio sudo[8948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:51 volumio sudo[8948]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:51 volumio volumio[8625]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:51 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 01:34:51 volumio volumio[8625]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:51 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 01:34:51 volumio systemd[1]: mpd.service: Consumed 5.337s CPU time. Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491334] CoreMusicLibrary::Adding element Last_100 Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491339] CoreMusicLibrary::Adding element Webradio Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 01:34:51 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 01:34:51 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:34:51 volumio volumio[8625]: info: Initializing BBC Radios Jan 10 01:34:51 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 01:34:51 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491422] CoreMusicLibrary::Adding element Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491434] CoreMusicLibrary::Adding element SoundCloud Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:51 volumio volumio[8625]: info: Creating Spotify config file Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:51 volumio sudo[8975]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 01:34:51 volumio sudo[8975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 01:34:51 volumio sudo[8975]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:51 volumio volumio[8625]: info: [squeezelite_mc] Starting proxy server... Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491796] CoreMusicLibrary::Adding element YouTube2 Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube2 Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491814] CoreMusicLibrary::Adding element YouTube Music Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube2 Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube Music Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491826] CoreMusicLibrary::Adding element Podcast Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube2 Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube Music Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Podcast Jan 10 01:34:51 volumio volumio[8625]: info: Loading i18n strings for locale en Jan 10 01:34:51 volumio volumio[8625]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Jan 10 01:34:51 volumio volumio[8625]: Updating browse sources language Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube2 Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube Music Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Podcast Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube2 Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube Music Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Podcast Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:51 volumio volumio[8625]: info: [1768030491873] CoreMusicLibrary::Adding element Volusonic Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube2 Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source YouTube Music Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Podcast Jan 10 01:34:51 volumio volumio[8625]: Cannot find translation for source Volusonic Jan 10 01:34:51 volumio volumio[8625]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Jan 10 01:34:51 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Jan 10 01:34:51 volumio volumio[8625]: info: Volumio Calling Home Jan 10 01:34:52 volumio volumio[8625]: info: [squeezelite_mc] Proxy server started on port 46527 Jan 10 01:34:52 volumio volumio[8625]: info: Preparing to generate the ALSA configuration file Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 01:34:52 volumio volumio[8625]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Jan 10 01:34:52 volumio volumio[8625]: info: Reading ALSA contributions from plugins. Jan 10 01:34:52 volumio volumio[8625]: info: MPD Permissions set Jan 10 01:34:52 volumio volumio[8625]: info: MPD Permissions set Jan 10 01:34:52 volumio volumio[8625]: info: Spotify config file written Jan 10 01:34:52 volumio sudo[8986]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 01:34:52 volumio sudo[8986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:52 volumio volumio[8625]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 01:34:52 volumio volumio[8625]: info: VolumeController:: Volume=100 Mute =false Jan 10 01:34:52 volumio volumio[8625]: info: CoreStateMachine::pushState Jan 10 01:34:52 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::volumioPushState Jan 10 01:34:52 volumio volumio[8625]: info: [squeezelite_mc] Server discovery started Jan 10 01:34:52 volumio volumio[8625]: info: [squeezelite_mc] Player finder started Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Jan 10 01:34:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:52 volumio volumio[8625]: info: No need to fix Spotify hosts Jan 10 01:34:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:52 volumio go-librespot[8990]: go-librespot daemon starting... Jan 10 01:34:52 volumio sudo[8986]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=debug msg="app state loaded" Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:52 volumio volumio[8625]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 10 01:34:52 volumio volumio[8625]: info: Volumio called home Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-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]" Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-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]" Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=info msg="zeroconf server listening on port 36433" Jan 10 01:34:52 volumio volumio[8625]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Jan 10 01:34:52 volumio volumio[8625]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Jan 10 01:34:52 volumio volumio[8625]: 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 Jan 10 01:34:52 volumio volumio[8625]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 01:34:52 volumio volumio[8625]: SPOTIFY: BQDZpzJOH80YU-BN0qo12QfrBWXrcGvVf0yYRkqwRwhKxEOnnRikWNDeU2WSk-wE8AySLcMLNW7LuvA9HGNipR-xeJPMwxOY10wNWtRMMtl1hvxQsiJAbKSQDJlWJg_xNG0_eBBddlmMTwi1vDYkg-SqHczHjbk1ugWvkPSTLoShSJZNwObmt8odv7ZYLlv-pW0Nk-0IpCdyKjKEEAou2ck89y3ovbmbA4_tvZg Jan 10 01:34:52 volumio volumio[8625]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jan 10 01:34:52 volumio volumio[8625]: info: New Spotify access token = BQDZpzJOH80YU-BN0qo12QfrBWXrcGvVf0yYRkqwRwhKxEOnnRikWNDeU2WSk-wE8AySLcMLNW7LuvA9HGNipR-xeJPMwxOY10wNWtRMMtl1hvxQsiJAbKSQDJlWJg_xNG0_eBBddlmMTwi1vDYkg-SqHczHjbk1ugWvkPSTLoShSJZNwObmt8odv7ZYLlv-pW0Nk-0IpCdyKjKEEAou2ck89y3ovbmbA4_tvZg Jan 10 01:34:52 volumio volumio[8625]: info: Spotify credentials grant success - running version from March 24, 2019 Jan 10 01:34:52 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.211.4 Jan 10 01:34:52 volumio avahi-daemon[664]: Registering new address record for 169.254.211.4 on eth0.IPv4. Jan 10 01:34:52 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:52 volumio volumio[8625]: info: Starting Shairport Sync Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=debug msg="obtained new client token: AAA6zDGY4Rz6Us8P+2jUx8qYjHhO+gMYATlXFMUgwCyLDsEL5IA6Vvx9jWXu7pyFk5ycdIZZqCsx7UU3yicMkfkbWHrqm33WDjMxSX67sCFr+cKZG5qkki3WSo5ltnXuPgGG4aMPXORjkDUqVcA7jbnqC49B4BwfW0wBFSiWryuwjwZy9cdHP6ALZZG2gfszoRjmhNF+17g2Uw6L/HL1tBuDgJ3jq8IlgXUv5lG/O2Jk1BNC3SFFfasURw==" Jan 10 01:34:52 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:52 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:52 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:52 volumio sudo[9010]: 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 Jan 10 01:34:52 volumio sudo[9010]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:52 volumio volumio[8625]: info: Starting Shairport Sync Jan 10 01:34:52 volumio volumio[8625]: info: Starting Shairport Sync Jan 10 01:34:52 volumio sudo[9010]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:52 volumio sudo[9024]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:52 volumio sudo[9024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:52 volumio sudo[9029]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:52 volumio sudo[9029]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:52 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 01:34:52 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 01:34:52 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:52 volumio systemd[1]: shairport-sync.service: Consumed 1.886s CPU time. Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:52 volumio go-librespot[9001]: time="2026-01-10T01:34:52-06:00" level=debug msg="completed challenge" Jan 10 01:34:52 volumio sudo[9034]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:52 volumio sudo[9034]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:53 volumio volumio[8625]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Jan 10 01:34:53 volumio go-librespot[9001]: time="2026-01-10T01:34:53-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:34:53 volumio volumio[8625]: info: Asound.conf file unchanged, so no further update is needed Jan 10 01:34:53 volumio volumio[8625]: info: Output device has changed, restarting MPD Jan 10 01:34:53 volumio volumio[8625]: info: Output device has changed, restarting Shairport Sync Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:53 volumio sudo[9041]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Jan 10 01:34:53 volumio sudo[9041]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:53 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:53 volumio sudo[9043]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 01:34:53 volumio sudo[9041]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:53 volumio sudo[9043]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:53 volumio sudo[9043]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:53 volumio sudo[9024]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:53 volumio sudo[9045]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 01:34:53 volumio sudo[9045]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:53 volumio volumio[8625]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 01:34:53 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 01:34:53 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 01:34:53 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:53 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:53 volumio sudo[9029]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:53 volumio sudo[9034]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:53 volumio volumio[8625]: info: MPD Permissions set Jan 10 01:34:53 volumio volumio[8625]: info: Shairport-Sync Started Jan 10 01:34:53 volumio systemd[1]: mpd.service: Deactivated successfully. Jan 10 01:34:53 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 01:34:53 volumio volumio[8625]: Error adding Membership: Error: addMembership EINVAL Jan 10 01:34:53 volumio systemd[1]: mpd.service: Consumed 1.722s CPU time. Jan 10 01:34:53 volumio volumio[8625]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Jan 10 01:34:53 volumio systemd[1]: mpd.socket: Deactivated successfully. Jan 10 01:34:53 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 01:34:53 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 01:34:53 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.211.4 Jan 10 01:34:53 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 01:34:53 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 01:34:53 volumio volumio[8625]: info: Shairport-Sync Started Jan 10 01:34:53 volumio volumio[8625]: info: Shairport-Sync Started Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio sudo[9072]: 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 Jan 10 01:34:53 volumio sudo[9072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:53 volumio sudo[9072]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::volumioGetState Jan 10 01:34:53 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:34:53 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Jan 10 01:34:53 volumio volumio[8625]: info: Starting Shairport Sync Jan 10 01:34:53 volumio sudo[9096]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Jan 10 01:34:53 volumio sudo[9096]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:53 volumio sudo[9098]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 01:34:53 volumio sudo[9098]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:53 volumio systemd[1]: Reloading. Jan 10 01:34:53 volumio volumio[8625]: 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"} Jan 10 01:34:53 volumio volumio[8625]: info: Spotify Successfully logged in Jan 10 01:34:53 volumio sudo[9086]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 01:34:53 volumio sudo[9086]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 01:34:53 volumio sudo[9086]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 01:34:53 volumio volumio[8625]: info: [1768030493707] CoreMusicLibrary::Adding element Spotify Jan 10 01:34:53 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 01:34:53 volumio volumio[8625]: Cannot find translation for source Bandcamp Discover Jan 10 01:34:53 volumio volumio[8625]: Cannot find translation for source SoundCloud Jan 10 01:34:53 volumio volumio[8625]: Cannot find translation for source YouTube2 Jan 10 01:34:53 volumio volumio[8625]: Cannot find translation for source YouTube Music Jan 10 01:34:53 volumio volumio[8625]: Cannot find translation for source Podcast Jan 10 01:34:53 volumio volumio[8625]: Cannot find translation for source Volusonic Jan 10 01:34:53 volumio volumio[8625]: Cannot find translation for source Spotify Jan 10 01:34:53 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.211.4 Jan 10 01:34:53 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.211.4 Jan 10 01:34:53 volumio avahi-daemon[664]: Withdrawing address record for 169.254.211.4 on eth0. Jan 10 01:34:53 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:53 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:53 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 01:34:54 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:54 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:54 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:34:54 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 01:34:55 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. Jan 10 01:34:55 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. Jan 10 01:34:55 volumio sudo[9096]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:55 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 01:34:55 volumio sudo[9138]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 01:34:55 volumio sudo[9138]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:55 volumio sudo[9138]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:55 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:55 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:55 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:55 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Jan 10 01:34:55 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 01:34:55 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 01:34:55 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:55 volumio systemd[1]: shairport-sync.service: Consumed 1.511s CPU time. Jan 10 01:34:55 volumio sudo[9141]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Jan 10 01:34:55 volumio sudo[9141]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:55 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 01:34:55 volumio sudo[9098]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:55 volumio volumio[8625]: info: Shairport-Sync Started Jan 10 01:34:55 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 10 01:34:55 volumio volumio[8625]: info: go-librespot daemon successfully initialized Jan 10 01:34:55 volumio systemd[1]: squeezelite.service: Deactivated successfully. Jan 10 01:34:55 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 10 01:34:55 volumio sudo[9141]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38. Jan 10 01:34:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:56 volumio go-librespot[9172]: go-librespot daemon starting... Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=debug msg="app state loaded" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=debug msg="stored credentials not found" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:34:56 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 01:34:56 volumio sudo[9180]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 01:34:56 volumio sudo[9180]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:56 volumio nmbd[1048]: [2026/01/10 01:34:56.425545, 0] ../../source3/libsmb/nmblib.c:923(send_udp) Jan 10 01:34:56 volumio nmbd[1048]: Packet send failed to 169.254.255.255(138) ERRNO=Network is unreachable Jan 10 01:34:56 volumio sudo[9180]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:56 volumio volumio[8625]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Jan 10 01:34:56 volumio sudo[9186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Jan 10 01:34:56 volumio sudo[9186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:56 volumio sudo[9186]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:56 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-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]" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-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]" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-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]" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=info msg="zeroconf server listening on port 36195" Jan 10 01:34:56 volumio sudo[9189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Jan 10 01:34:56 volumio sudo[9189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=debug msg="obtained new client token: AADFkoS1TAJ3qWMSmd65QS52No6EmTW6grzmDncE0dyslgsK0P3bksCJfnjGm+LfxozxfvErODxwrSy3J8tBgAH6nUuEx0pA5Af33yKRuU43dz5yftu9F1alAOmpXMOPNZu6G6uul/x2UZT0Npclf1XZxTE29xdeVRxC/AYxRuer20/D0Yebz+RRrfa/muHpGs2ltnQDc8RJfzN/o6sJ0ed1MCaHl34VzrLmDzeTnVss6qIdNo1/higaDw==" Jan 10 01:34:56 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Jan 10 01:34:56 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Jan 10 01:34:56 volumio sudo[9189]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=debug msg="completed keyexchange" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=debug msg="completed challenge" Jan 10 01:34:56 volumio go-librespot[9173]: time="2026-01-10T01:34:56-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:34:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:34:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:34:57 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 01:34:57 volumio sudo[9196]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 01:34:57 volumio sudo[9196]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:57 volumio sudo[9196]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:57 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 01:34:57 volumio sudo[9199]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 01:34:57 volumio sudo[9199]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:57 volumio sudo[9199]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:58 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 01:34:58 volumio sudo[9202]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 01:34:58 volumio sudo[9202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:58 volumio mpd[9136]: 2026-01-10T01:34:58 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 01:34:58 volumio sudo[9202]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:58 volumio systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 01:34:58 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:34:58 volumio sudo[8950]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:58 volumio sudo[9045]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:58 volumio sudo[8940]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:58 volumio volumio[8625]: error: MPD error: The expression evaluated to a falsy value: Jan 10 01:34:58 volumio volumio[8625]: assert.ok(self.idling) Jan 10 01:34:58 volumio volumio[8625]: error: The expression evaluated to a falsy value: Jan 10 01:34:58 volumio volumio[8625]: assert.ok(self.idling) Jan 10 01:34:58 volumio volumio[8625]: error: MPD error: The expression evaluated to a falsy value: Jan 10 01:34:58 volumio volumio[8625]: assert.ok(self.idling) Jan 10 01:34:58 volumio volumio[8625]: error: The expression evaluated to a falsy value: Jan 10 01:34:58 volumio volumio[8625]: assert.ok(self.idling) Jan 10 01:34:58 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:34:58 volumio volumio[8625]: error: updateQueue error: null Jan 10 01:34:58 volumio volumio[8625]: info: MPD running with PID9136 Jan 10 01:34:58 volumio volumio[8625]: ,establishing connection Jan 10 01:34:58 volumio volumio[8625]: error: updateQueue error: null Jan 10 01:34:58 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.23.201 Jan 10 01:34:58 volumio avahi-daemon[664]: Registering new address record for 169.254.23.201 on eth0.IPv4. Jan 10 01:34:58 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:34:59 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:59 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:59 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:59 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 01:34:59 volumio sudo[9228]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 01:34:59 volumio sudo[9228]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:59 volumio sudo[9228]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:59 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.23.201 Jan 10 01:34:59 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.23.201 Jan 10 01:34:59 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.23.201 Jan 10 01:34:59 volumio avahi-daemon[664]: Withdrawing address record for 169.254.23.201 on eth0. Jan 10 01:34:59 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:34:59 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:34:59 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:59 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:34:59 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:34:59 volumio volumio[8625]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Jan 10 01:34:59 volumio sudo[9247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Jan 10 01:34:59 volumio sudo[9247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:34:59 volumio sudo[9247]: pam_unix(sudo:session): session closed for user root Jan 10 01:34:59 volumio volumio[8625]: info: Completed starting Core Plugins Jan 10 01:34:59 volumio volumio[8625]: info: ------------------------------------------- Jan 10 01:34:59 volumio volumio[8625]: info: ----- MyVolumio plugins startup ---- Jan 10 01:34:59 volumio volumio[8625]: info: ------------------------------------------- Jan 10 01:34:59 volumio volumio[8625]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 10 01:34:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39. Jan 10 01:34:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:34:59 volumio go-librespot[9249]: go-librespot daemon starting... Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="app state loaded" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=info msg="zeroconf server listening on port 37315" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="obtained new client token: AAAusKgJVL2Pkebiv1h/qqw3jYgE0GIpDSA15IGJur3SCor+zi1P5op632VOig/4WQqVTTo14e+DOrkyw0VOykUurAQMItZig7gecFmWBWYctUhYIxMEJRymNILpwNTQMXTz0Q0DHK/bGzehK5Edzhup8I7JaNb8w9fyqTxKFzdcwQo5FsnL9UXzW3OFxx54LwwUf441TG2dGwwry0WHaG7J+7GD5LeQyGYW66yP6KobJnxeaaD8e4tNNA==" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=debug msg="completed challenge" Jan 10 01:35:00 volumio go-librespot[9250]: time="2026-01-10T01:35:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:01 volumio sudo[9259]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 01:35:01 volumio sudo[9259]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:35:01 volumio sudo[9261]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 01:35:01 volumio sudo[9261]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:35:01 volumio sudo[9263]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 01:35:01 volumio sudo[9263]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:35:01 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 01:35:01 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:01 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 01:35:01 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 01:35:01 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:01 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 01:35:01 volumio sudo[9261]: pam_unix(sudo:session): session closed for user root Jan 10 01:35:01 volumio sudo[9259]: pam_unix(sudo:session): session closed for user root Jan 10 01:35:01 volumio sudo[9263]: pam_unix(sudo:session): session closed for user root Jan 10 01:35:01 volumio mpd_monitor.sh[9267]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 01:35:01 volumio volumio[8625]: info: Successfully started MPD Monitor Jan 10 01:35:01 volumio volumio[8625]: info: Successfully started MPD Monitor Jan 10 01:35:01 volumio volumio[8625]: info: Successfully started MPD Monitor Jan 10 01:35:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40. Jan 10 01:35:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:03 volumio go-librespot[9273]: go-librespot daemon starting... Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35:03-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35:03-06:00" level=debug msg="app state loaded" Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35:03-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35:03-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35:03-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]" Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35:03-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]" Jan 10 01:35:03 volumio go-librespot[9274]: time="2026-01-10T01:35:03-06:00" level=info msg="zeroconf server listening on port 36921" Jan 10 01:35:04 volumio go-librespot[9274]: time="2026-01-10T01:35:04-06:00" level=debug msg="obtained new client token: AACzBmY5cTSFq1xcDae6PHJZmQB/lRGlq/TXMc8eVsz0dpoMR7wHj5qrbsEovri3oXoLXH0YJFU0FQzZYpARe73nLkc2nQyz/dU5nPJW83WlHzmfyp4xoB1Q/iLM6kPeF7d8gU9fUbq1k7rEnn884AR+Su1dIJkO9oVzYlw+ZjpY60uhxtusqWQNLCdSSP5thCWQxVhphNEUAr6/en/MZ3dwUSTf+DZFv6kfH5MXLbEhqLQ9IyagMbw=" Jan 10 01:35:04 volumio go-librespot[9274]: time="2026-01-10T01:35:04-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Jan 10 01:35:04 volumio go-librespot[9274]: time="2026-01-10T01:35:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Jan 10 01:35:04 volumio go-librespot[9274]: time="2026-01-10T01:35:04-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:04 volumio go-librespot[9274]: time="2026-01-10T01:35:04-06:00" level=debug msg="completed challenge" Jan 10 01:35:04 volumio go-librespot[9274]: time="2026-01-10T01:35:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:04 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.60.72 Jan 10 01:35:04 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:35:04 volumio avahi-daemon[664]: Registering new address record for 169.254.60.72 on eth0.IPv4. Jan 10 01:35:04 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:04 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:04 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:04 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.60.72 Jan 10 01:35:04 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:05 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.60.72 Jan 10 01:35:05 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.60.72 Jan 10 01:35:05 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:35:05 volumio avahi-daemon[664]: Withdrawing address record for 169.254.60.72 on eth0. Jan 10 01:35:05 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:05 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:05 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:05 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:05 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:35:06 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 01:35:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41. Jan 10 01:35:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:07 volumio go-librespot[9330]: go-librespot daemon starting... Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-06:00" level=debug msg="app state loaded" Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-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]" Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-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]" Jan 10 01:35:07 volumio go-librespot[9331]: time="2026-01-10T01:35:07-06:00" level=info msg="zeroconf server listening on port 39783" Jan 10 01:35:08 volumio go-librespot[9331]: time="2026-01-10T01:35:08-06:00" level=debug msg="obtained new client token: AADas0Ycv+R4L5j269MkycUxnoCD9w64f4A4J0ZGTCHe3g/iO2FSEr8EJw5qS66yA28QjNiSkafPo5AEqFVZRioe/A8h8ZJPcCVXSDmtIy2nnZNKoJx+5K7AK35PMg9DhM6bMJlsg1x4QmP0SzYNHb7VS5SE8HE3XuCGKH8oMSlaefV1+EdxhqlcNo9Q3s7ghoRdb27QSkNDaFfS27poxhxtfV6u/wZz6+pK0r9rumZo2jv+m6/3zBQ=" Jan 10 01:35:08 volumio go-librespot[9331]: time="2026-01-10T01:35:08-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:08 volumio go-librespot[9331]: time="2026-01-10T01:35:08-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:08 volumio go-librespot[9331]: time="2026-01-10T01:35:08-06:00" level=debug msg="completed challenge" Jan 10 01:35:08 volumio go-librespot[9331]: time="2026-01-10T01:35:08-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:08 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:08 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 10 01:35:08 volumio volumio[8625]: info: Adding plugin bluetooth to MyMusic Plugins Jan 10 01:35:08 volumio volumio[8625]: info: Adding plugin multiroom to MyMusic Plugins Jan 10 01:35:08 volumio volumio[8625]: info: Adding plugin metavolumio to MyMusic Plugins Jan 10 01:35:08 volumio volumio[8625]: info: Adding plugin cd_controller to MyMusic Plugins Jan 10 01:35:08 volumio volumio[8625]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 10 01:35:08 volumio volumio[8625]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 10 01:35:08 volumio volumio[8625]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 10 01:35:08 volumio volumio[8625]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 10 01:35:09 volumio volumio[8625]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 10 01:35:09 volumio volumio[8625]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 10 01:35:09 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:09 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:09 volumio volumio[8625]: info: Starting MyVolumio Remote Streaming Endpoints Jan 10 01:35:09 volumio volumio[8625]: info: MyVolumio login type: Token Jan 10 01:35:09 volumio volumio[8625]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 10 01:35:09 volumio volumio[8625]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 10 01:35:11 volumio volumio[8625]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 10 01:35:11 volumio volumio[8625]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 10 01:35:11 volumio volumio[8625]: info: Streaming services startup Jan 10 01:35:11 volumio volumio[8625]: info: Starting Streaming Daemon Jan 10 01:35:11 volumio sudo[9340]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 10 01:35:11 volumio sudo[9340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:35:11 volumio volumio[8625]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 10 01:35:11 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.243.184 Jan 10 01:35:11 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:35:11 volumio avahi-daemon[664]: Registering new address record for 169.254.243.184 on eth0.IPv4. Jan 10 01:35:11 volumio sudo[9340]: pam_unix(sudo:session): session closed for user root Jan 10 01:35:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:11 volumio volumio[8625]: error: Cannot start Volumio Streaming Daemon Jan 10 01:35:11 volumio volumio[8625]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 10 01:35:11 volumio volumio[8625]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 10 01:35:11 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.243.184 Jan 10 01:35:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42. Jan 10 01:35:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:11 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:11 volumio go-librespot[9362]: go-librespot daemon starting... Jan 10 01:35:11 volumio go-librespot[9363]: time="2026-01-10T01:35:11-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:11 volumio go-librespot[9363]: time="2026-01-10T01:35:11-06:00" level=debug msg="app state loaded" Jan 10 01:35:11 volumio go-librespot[9363]: time="2026-01-10T01:35:11-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:11 volumio go-librespot[9363]: time="2026-01-10T01:35:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:11 volumio volumio[8625]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jan 10 01:35:11 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.243.184 Jan 10 01:35:11 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.243.184 Jan 10 01:35:11 volumio avahi-daemon[664]: Withdrawing address record for 169.254.243.184 on eth0. Jan 10 01:35:11 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:35:11 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:35:11 volumio go-librespot[9363]: time="2026-01-10T01:35:11-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:35:11 volumio go-librespot[9363]: time="2026-01-10T01:35:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:35:11 volumio go-librespot[9363]: time="2026-01-10T01:35:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:35:11 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:11 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:11 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:12 volumio go-librespot[9363]: time="2026-01-10T01:35:12-06:00" level=info msg="zeroconf server listening on port 34429" Jan 10 01:35:12 volumio go-librespot[9363]: time="2026-01-10T01:35:12-06:00" level=debug msg="obtained new client token: AADbAPGy60T3wjfr+nJ9Umw0CIBleRlJYfRwD//Oi637SqDYKZGBXcaEr7dZmpQu4CBRpO6Tnzg+mOXEHHksrxJn59pW40m5M3Dj/vxhIQjFlPc0FEK3z+8XtXJSkYiw9ob+jMn97KuBH0eUUWiu+ONtnGpjSRgfg9f3Lz1G+DY8OECNL78IryUsKdUWdZH0mxcXFCx8kA9qK/G1SXK5I9IqqaPjdZI5UmNxMyQS+Mj+hfkxctOVVD8=" Jan 10 01:35:12 volumio go-librespot[9363]: time="2026-01-10T01:35:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:12 volumio volumio[8625]: info: MyVolumio token set successfully Jan 10 01:35:12 volumio volumio[8625]: info: MYVOLUMIO: Adding device Jan 10 01:35:12 volumio volumio[8625]: info: MYVOLUMIO: Evaluating Server Jan 10 01:35:12 volumio go-librespot[9363]: time="2026-01-10T01:35:12-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:12 volumio go-librespot[9363]: time="2026-01-10T01:35:12-06:00" level=debug msg="completed challenge" Jan 10 01:35:12 volumio go-librespot[9363]: time="2026-01-10T01:35:12-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:12 volumio volumio[8625]: info: MyVolumio status changed Jan 10 01:35:12 volumio volumio[8625]: info: Streaming services startup Jan 10 01:35:12 volumio volumio[8625]: info: Starting Streaming Daemon Jan 10 01:35:12 volumio volumio[8625]: info: Removing browser output: myVolumio user plan is not superstar Jan 10 01:35:12 volumio volumio[8625]: info: Removing audio output: Jan 10 01:35:12 volumio volumio[8625]: info: Stoppping Tunnel 1 Jan 10 01:35:12 volumio sudo[9407]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 10 01:35:12 volumio sudo[9407]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:35:12 volumio sudo[9409]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jan 10 01:35:12 volumio sudo[9409]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:35:12 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. Jan 10 01:35:12 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. Jan 10 01:35:12 volumio sudo[9407]: pam_unix(sudo:session): session closed for user root Jan 10 01:35:12 volumio volumio[8625]: error: Cannot start Volumio Streaming Daemon Jan 10 01:35:12 volumio volumio[8625]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 10 01:35:12 volumio volumio[8625]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 10 01:35:12 volumio volumio[8625]: info: Setting Geolocation for MyVolumio to us1 Jan 10 01:35:12 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:12 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:12 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:12 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. Jan 10 01:35:12 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. Jan 10 01:35:12 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. Jan 10 01:35:12 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. Jan 10 01:35:12 volumio sudo[9409]: pam_unix(sudo:session): session closed for user root Jan 10 01:35:12 volumio volumio[8625]: info: Remote SSH Stopped Jan 10 01:35:13 volumio volumio[8625]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Jan 10 01:35:13 volumio volumio[8625]: info: Updating MyVolumio device info Jan 10 01:35:13 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:13 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:13 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:14 volumio volumio[8625]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Jan 10 01:35:14 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:14 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 43. Jan 10 01:35:15 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:15 volumio go-librespot[9412]: go-librespot daemon starting... Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=debug msg="app state loaded" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35: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]" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35: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]" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35: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]" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=info msg="zeroconf server listening on port 46197" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=debug msg="obtained new client token: AAB5kY2sqRNdsVGbZTV7NoBHS4xKf/AXD3IoEeXZOdOOVvnVXfBQgBqsO/84vMEuiuu5asd17d5GLmhsnJ1glfaONaH0NQN1EKXAS42nEsIaocGRFgblQ7JvYKzqppKM6cNYedRAziGZSOd1LPLdXhwfiSe/0klKb1nK0o/EJ2ZnwM2rX3F5aJkWze37DCiUErwSXbQWooHxDjufLkWQQE+/TKV91QEvAidhInlScqQRcvlX/hZ4Bvnbeg==" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35:15-06:00" level=debug msg="completed challenge" Jan 10 01:35:15 volumio go-librespot[9413]: time="2026-01-10T01:35: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 " Jan 10 01:35:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:16 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 01:35:16 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.174.211 Jan 10 01:35:16 volumio avahi-daemon[664]: Registering new address record for 169.254.174.211 on eth0.IPv4. Jan 10 01:35:16 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:35:16 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:16 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:16 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:16 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.174.211 Jan 10 01:35:17 volumio volumio[8625]: info: MYVOLUMIO: Adding device Jan 10 01:35:17 volumio volumio[8625]: info: MYVOLUMIO: Evaluating Server Jan 10 01:35:17 volumio volumio[8625]: info: Setting Geolocation for MyVolumio to us1 Jan 10 01:35:17 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:17 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:17 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:17 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:17 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:17 volumio volumio[8625]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Jan 10 01:35:17 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.174.211 Jan 10 01:35:17 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.174.211 Jan 10 01:35:17 volumio avahi-daemon[664]: Withdrawing address record for 169.254.174.211 on eth0. Jan 10 01:35:17 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:35:17 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:35:17 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:17 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:17 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:18 volumio volumio[8625]: info: Updating MyVolumio device info Jan 10 01:35:18 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:18 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:18 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:18 volumio volumio[8625]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Jan 10 01:35:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44. Jan 10 01:35:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:19 volumio go-librespot[9485]: go-librespot daemon starting... Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="app state loaded" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=info msg="zeroconf server listening on port 33429" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="obtained new client token: AAD1It96s/0m2Oy4AySroj2fBWSX3LwkqTaLWWO2svaMJAXM/F8xIabRLHSIx63Ht+4hrUv37teXXU4QL/lTHUDFqGEfruSPWga3zgZb0SSYeBVTEpX6Csa3U1gHg48OFY9WkEI/H58WhfT9Dr1DM4mqPfxtSUHj8njZEzuRpRtN28uIFU0DSd3UgRthwlmjDUVHas0nk6bdzi6a43wtr70tJJLoao22FP+L/9nnm2IYmIl1GDjjuc8ykw==" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35:19-06:00" level=debug msg="completed challenge" Jan 10 01:35:19 volumio go-librespot[9486]: time="2026-01-10T01:35: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 " Jan 10 01:35:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:20 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:20 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:21 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:35:21 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:21 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jan 10 01:35:21 volumio volumio-remote-updater[14193]: Test mode disabled Jan 10 01:35:21 volumio volumio-remote-updater[14193]: Alpha mode disabled Jan 10 01:35:21 volumio volumio-remote-updater[14193]: Alpha legacy test mode disabled Jan 10 01:35:21 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Jan 10 01:35:22 volumio volumio[8625]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

ANNOUNCEMENT

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

FIX

\n
    \n
  • Nodejs 20.5.1 version pinning with static package fallback
    • \n
\n","title":"Update v4.073","updateavailable":true} Jan 10 01:35:22 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jan 10 01:35:22 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.142.226 Jan 10 01:35:22 volumio avahi-daemon[664]: Registering new address record for 169.254.142.226 on eth0.IPv4. Jan 10 01:35:22 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:35:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 45. Jan 10 01:35:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:22 volumio go-librespot[9516]: go-librespot daemon starting... Jan 10 01:35:22 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:22 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:22 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:22 volumio go-librespot[9517]: time="2026-01-10T01:35:22-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:22 volumio go-librespot[9517]: time="2026-01-10T01:35:22-06:00" level=debug msg="app state loaded" Jan 10 01:35:22 volumio go-librespot[9517]: time="2026-01-10T01:35:22-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:22 volumio go-librespot[9517]: time="2026-01-10T01:35:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.142.226 Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=info msg="zeroconf server listening on port 35981" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=debug msg="obtained new client token: AACHx42Eotd73YnIr1vvYQeF6Ic3xm30bHuJaN9H/yMgODOMCp1WqZ0rnnbySaDw5yN21uqL0TSBB1wnEE1KRIRjbsJGJLYUY6Mc8HwcEhjyuCiXLkd4urwgVIJX2gU7BWl6PjXiI3eV3/RKavuk3oZV073hgO+iol384+fx/Fq/qUpZVcaLVr0+U7bT1q0kSPHUMAOlJsN0E9lGKkX9XGaYGCklFcVYU6zeb3bxQivCbD4lPZMzJ+/3uA==" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=debug msg="completed challenge" Jan 10 01:35:23 volumio go-librespot[9517]: time="2026-01-10T01:35:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:23 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:23 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:23 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.142.226 Jan 10 01:35:23 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.142.226 Jan 10 01:35:23 volumio avahi-daemon[664]: Withdrawing address record for 169.254.142.226 on eth0. Jan 10 01:35:23 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:35:23 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:35:23 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:23 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:23 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:24 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jan 10 01:35:24 volumio volumio[8625]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jan 10 01:35:24 volumio volumio[8625]: info: CoreCommandRouter::volumioGetState Jan 10 01:35:24 volumio volumio[8625]: info: CorePlayQueue::getTrack 0 Jan 10 01:35:26 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:26 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46. Jan 10 01:35:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:26 volumio go-librespot[9555]: go-librespot daemon starting... Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=debug msg="app state loaded" Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 01:35:26 volumio go-librespot[9556]: time="2026-01-10T01:35:26-06:00" level=info msg="zeroconf server listening on port 42373" Jan 10 01:35:27 volumio go-librespot[9556]: time="2026-01-10T01:35:27-06:00" level=debug msg="obtained new client token: AABeysMXQv+5bWwmrm5269NMqmD/HXvWim5EPVFSLCAR6LcLcc7hMbaoVDRLhhbX7Mtn0ENuTBydP28yanuowycGEBWUxp1NiqyyLWMuGnafqNE9vm7X84+EgInzkNhir2pRTHdBSpKlJooSQPXk/aVtXk4b9UJXlxLE+d5HFtNCmoevp/qRp6Tt0k+B7D8BcGWdGuwC7Lpy3wclrDZCmg3NaloYoxNKfq5b9T+CluRbcIfTpXjulYA=" Jan 10 01:35:27 volumio go-librespot[9556]: time="2026-01-10T01:35:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:27 volumio go-librespot[9556]: time="2026-01-10T01:35:27-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:27 volumio go-librespot[9556]: time="2026-01-10T01:35:27-06:00" level=debug msg="completed challenge" Jan 10 01:35:27 volumio go-librespot[9556]: time="2026-01-10T01:35:27-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:28 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.92.177 Jan 10 01:35:28 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:35:28 volumio avahi-daemon[664]: Registering new address record for 169.254.92.177 on eth0.IPv4. Jan 10 01:35:28 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:28 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:28 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:29 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.92.177 Jan 10 01:35:29 volumio ntpd[872]: IO: Listen normally on 11132 eth0 169.254.92.177:123 Jan 10 01:35:29 volumio ntpd[872]: IO: new interface(s) found: waking up resolver Jan 10 01:35:29 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:35:29 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:35:29 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jan 10 01:35:29 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jan 10 01:35:29 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jan 10 01:35:29 volumio volumio[8625]: info: CoreCommandRouter::volumioGetBrowseSources Jan 10 01:35:29 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 01:35:29 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:29 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:29 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.92.177 Jan 10 01:35:29 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.92.177 Jan 10 01:35:29 volumio avahi-daemon[664]: Withdrawing address record for 169.254.92.177 on eth0. Jan 10 01:35:29 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:35:29 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:35:29 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:29 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:29 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 47. Jan 10 01:35:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:30 volumio go-librespot[9595]: go-librespot daemon starting... Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="app state loaded" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=info msg="zeroconf server listening on port 34839" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="obtained new client token: AADv3Zt9DLXrgxMjc0mcVxuEibqNQLODHseS/7R0XgNzPa1nMxTbLcwj+OI6dAf/Rsa/46gEZe4QAzIU4hLAK7wAwNAv5X4FHv/6yktUyrno/4hWlzrHxjn/GG8PmhVinXyi/PDubQgvf793di+0/vLMBKvLCa66LU8suQYjFR+MNO0s0keik9W3YdwdWsJDaOxa2uWAtf7Y3N4Z2iuyidoU7o+1FqA8Pn4nJt4UKFJPV5xnKgqOXhfAjg==" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=debug msg="completed challenge" Jan 10 01:35:30 volumio go-librespot[9596]: time="2026-01-10T01:35:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:31 volumio volumio[8625]: error: MyVolumio Plugin failed to authenticate in a timely fashion Jan 10 01:35:31 volumio volumio[8625]: info: Completed starting MyVolumio Plugin Jan 10 01:35:31 volumio volumio[8625]: [Metrics] CommandRouter: 57s 611.90ms Jan 10 01:35:31 volumio volumio[8625]: info: CoreCommandRouter::volumiosetStartupVolume Jan 10 01:35:31 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 01:35:31 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 01:35:31 volumio volumio[8625]: info: CoreCommandRouter::Close All Modals sent Jan 10 01:35:31 volumio volumio[8625]: info: CoreCommandRouter::Close All Modals sent Jan 10 01:35:31 volumio ntpd[872]: IO: Deleting interface #11132 eth0, 169.254.92.177#123, interface stats: received=0, sent=0, dropped=0, active_time=2 secs Jan 10 01:35:32 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jan 10 01:35:32 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jan 10 01:35:32 volumio volumio[8625]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jan 10 01:35:32 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:32 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:33 volumio kernel: hwmon hwmon1: Undervoltage detected! Jan 10 01:35:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48. Jan 10 01:35:34 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:34 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:34 volumio go-librespot[9610]: go-librespot daemon starting... Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=debug msg="app state loaded" Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:34 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.119.216 Jan 10 01:35:34 volumio avahi-daemon[664]: Registering new address record for 169.254.119.216 on eth0.IPv4. Jan 10 01:35:34 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:35:34 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:34 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:34 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:34 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.119.216 Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-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]" Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-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]" Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=info msg="zeroconf server listening on port 43299" Jan 10 01:35:34 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.119.216 Jan 10 01:35:34 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.119.216 Jan 10 01:35:34 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:35:34 volumio avahi-daemon[664]: Withdrawing address record for 169.254.119.216 on eth0. Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=debug msg="obtained new client token: AAAg1Rlx6CZkj8dnXSe8KOYXDDB2R8NKbzzAFYyJHWBmYeVIINMw1eAaeUEMmkniTIPvMaYx4WuSpowzPz28G5Cp7lczZPpIEuzr5KVQRl1tiZGBRx6Oe8vergvdy2VRxq4F7JYgMIZpVqFmcZ0NsQvG9ArrxTq8Rmt7lejfNeSfVXlH2sWcXMG1whWWhkZthodrY8iYSrpVZcnc3Nm9/VAnhRtEikckpTI2rc7yfCHOV1XEzS+C+wgCTg==" Jan 10 01:35:34 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:35:34 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:34 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:34 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:34 volumio go-librespot[9611]: time="2026-01-10T01:35:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:35 volumio go-librespot[9611]: time="2026-01-10T01:35:35-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:35 volumio go-librespot[9611]: time="2026-01-10T01:35:35-06:00" level=debug msg="completed challenge" Jan 10 01:35:35 volumio go-librespot[9611]: time="2026-01-10T01:35:35-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:35 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:35 volumio volumio[8625]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:38 volumio volumio[8625]: info: BOOT COMPLETED Jan 10 01:35:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49. Jan 10 01:35:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:38 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:38 volumio go-librespot[9664]: go-librespot daemon starting... Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=debug msg="app state loaded" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-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]" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-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]" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-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]" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=info msg="zeroconf server listening on port 40051" Jan 10 01:35:38 volumio volumio[8625]: info: Initializing connection to go-librespot Websocket Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=debug msg="new websocket client" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=debug msg="obtained new client token: AAAfcPUYqxc1x+v3d+11zIoOgJBH5A0ujf02uJZ8e2YqU0A8wMNwfVv2S6CzUhY/Hn1p+bZwh78TSf/ioVju4VTNHA2iXggKBCtzSvcs5MqQxdqvB/gi3/hbssPoT4GXbi1Ow1jrBchbb6I2KLVoEqeacEhfdudyaH2G0GHJYBjnX7moGnwIHDT3t9jXYDX2YWVIdXl+qPLvzQL6R9TX3UswizGBWrTC+dZyC4m3QgyNMMyoboHiZfnYcg==" Jan 10 01:35:38 volumio volumio[8625]: info: Connection to go-librespot Websocket established Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=debug msg="completed keyexchange" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=debug msg="completed challenge" Jan 10 01:35:38 volumio go-librespot[9665]: time="2026-01-10T01:35:38-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Jan 10 01:35:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 01:35:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 01:35:38 volumio volumio[8625]: info: Connection to go-librespot Websocket closed Jan 10 01:35:39 volumio kernel: hwmon hwmon1: Voltage normalised Jan 10 01:35:39 volumio dhcpcd[684]: eth0: using IPv4LL address 169.254.233.209 Jan 10 01:35:39 volumio dhcpcd[684]: eth0: adding route to 169.254.0.0/16 Jan 10 01:35:39 volumio avahi-daemon[664]: Registering new address record for 169.254.233.209 on eth0.IPv4. Jan 10 01:35:39 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:39 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:39 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:40 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.233.209 Jan 10 01:35:40 volumio dhcpcd[684]: eth0: 80:69:1a:20:db:59(80:69:1a:20:db:59) claims 169.254.233.209 Jan 10 01:35:40 volumio dhcpcd[684]: eth0: 10 second defence failed for 169.254.233.209 Jan 10 01:35:40 volumio dhcpcd[684]: eth0: deleting route to 169.254.0.0/16 Jan 10 01:35:40 volumio avahi-daemon[664]: Withdrawing address record for 169.254.233.209 on eth0. Jan 10 01:35:40 volumio dhcpcd[684]: eth0: probing for an IPv4LL address Jan 10 01:35:40 volumio systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:40 volumio systemd[1]: Stopping ip-changed@eth0.target - IP Address changed on eth0... Jan 10 01:35:40 volumio systemd[1]: Reached target ip-changed@eth0.target - IP Address changed on eth0. Jan 10 01:35:41 volumio volumio[8625]: info: Getting Spotify volume Jan 10 01:35:41 volumio volumio[8625]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 01:35:41 volumio volumio[8625]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 01:35:41 volumio volumio[8625]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 10 01:35:41 volumio volumio[8625]: errno: -111, Jan 10 01:35:41 volumio volumio[8625]: code: 'ECONNREFUSED', Jan 10 01:35:41 volumio volumio[8625]: syscall: 'connect', Jan 10 01:35:41 volumio volumio[8625]: address: '127.0.0.1', Jan 10 01:35:41 volumio volumio[8625]: port: 9879, Jan 10 01:35:41 volumio volumio[8625]: response: undefined Jan 10 01:35:41 volumio volumio[8625]: } Jan 10 01:35:41 volumio volumio[8625]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 01:35:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50. Jan 10 01:35:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 01:35:42 volumio go-librespot[9717]: go-librespot daemon starting... Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=info msg="running go-librespot 0.4.0" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=debug msg="app state loaded" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=debug msg="stored credentials not found" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 01:35:42 volumio sudo[9730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 01:34' Jan 10 01:35:42 volumio sudo[9730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-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]" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-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]" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=info msg="zeroconf server listening on port 43473" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=debug msg="obtained new client token: AABzWBn+h2/BcAo8Ta1V0pDqP2sUIhwZdB47VkdFJ2ykOzwK1Pfc1+GVbqQbvM/jpIWoLUqy4yOMQ7yWf7a5S4r5/2M0N1pQeYXUJ00q9LaNf6HvRrV5M0baQcWdAayiFsKzH2MpNSglNoTL67wddqBvrnQtl/bR4XcfHafuZGV59nXVyLFGSan9kxWFlPM2nIuP1emV2PyLIVOqapZFllgORtnaYGazJCe8WFTOT+qUipTJLVIbM275mQ==" Jan 10 01:35:42 volumio go-librespot[9721]: time="2026-01-10T01:35:42-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" 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"