Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="app state loaded"
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:00 volumio sudo[31897]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 06:20'
Dec 09 06:21:00 volumio sudo[31897]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=info msg="zeroconf server listening on port 45083"
Dec 09 06:21:00 volumio sudo[31897]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="obtained new client token: AABjm0WlAj2IgEgoUzS2OSXFWq4XWXsfOt6T9hX3EXCDknI8OFbvwts+5rgeJO/lf7A0OA2HOAn9bP327zsILtCLKmIO5Ihh8VYlRxL9X6CxZGInF1+hFQu4BZM+V6r/laLmERvHuXhB6NzpirVkmeXzugsT+Y1nkZn6Imj9ZP3ee7CpmQGDeeqLa1YSOvAD1I5rfNS2SVT6oYFCFFoIpBxdnMVfeacRTrupTrgwdElyLT2W5ojIiyjxCQ=="
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:00 volumio volumio-remote-updater[9752]: [2025-12-09 06:21:00] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 09 06:21:00 volumio volumio-remote-updater[9752]: [2025-12-09 06:21:00] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 09 06:21:00 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:00 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 09 06:21:00 volumio systemd[1]: volumio.service: Consumed 45.687s CPU time.
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=debug msg="completed challenge"
Dec 09 06:21:00 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 06:21:00 volumio go-librespot[31889]: time="2025-12-09T06:21:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:00 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 06:21:00 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 24142.
Dec 09 06:21:00 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 06:21:00 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 09 06:21:00 volumio systemd[1]: volumio.service: Consumed 45.687s CPU time.
Dec 09 06:21:00 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 09 06:21:01 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 06:21:02 volumio volumio[31911]: info: -------------------------------------------
Dec 09 06:21:02 volumio volumio[31911]: info: ----- Volumio3 ----
Dec 09 06:21:02 volumio volumio[31911]: info: -------------------------------------------
Dec 09 06:21:02 volumio volumio[31911]: info: ----- System startup ----
Dec 09 06:21:02 volumio volumio[31911]: info: -------------------------------------------
Dec 09 06:21:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7.
Dec 09 06:21:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:03 volumio volumio[31911]: info: MYVOLUMIO Environment detected
Dec 09 06:21:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:03 volumio go-librespot[31932]: go-librespot daemon starting...
Dec 09 06:21:03 volumio volumio[31911]: info: Plugin folders cleanup
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning into folder /volumio/app/plugins/
Dec 09 06:21:03 volumio go-librespot[31936]: time="2025-12-09T06:21:03-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category audio_interface
Dec 09 06:21:03 volumio go-librespot[31936]: time="2025-12-09T06:21:03-06:00" level=debug msg="app state loaded"
Dec 09 06:21:03 volumio go-librespot[31936]: time="2025-12-09T06:21:03-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:03 volumio go-librespot[31936]: time="2025-12-09T06:21:03-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category miscellanea
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category music_service
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category plugins.json
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category system_controller
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category user_interface
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning into folder /data/plugins/
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category audio_interface
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category music_service
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category system_controller
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category system_hardware
Dec 09 06:21:03 volumio volumio[31911]: info: Scanning category user_interface
Dec 09 06:21:03 volumio volumio[31911]: info: Plugin folders cleanup completed
Dec 09 06:21:03 volumio volumio[31911]: info: -------------------------------------------
Dec 09 06:21:03 volumio volumio[31911]: info: ----- Core plugins startup ----
Dec 09 06:21:03 volumio volumio[31911]: info: -------------------------------------------
Dec 09 06:21:03 volumio volumio[31911]: info: Loading plugins from folder /volumio/app/plugins/
Dec 09 06:21:03 volumio volumio[31911]: info: Adding plugin upnp to MyMusic Plugins
Dec 09 06:21:03 volumio volumio[31911]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 09 06:21:03 volumio volumio[31911]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 09 06:21:03 volumio volumio[31911]: info: Loading plugins from folder /data/plugins/
Dec 09 06:21:03 volumio volumio[31911]: info: Loading plugin "system"...
Dec 09 06:21:03 volumio volumio[31911]: info: Loading plugin "appearance"...
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=info msg="zeroconf server listening on port 43053"
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=debug msg="obtained new client token: AAC+j6xEaW1NsGmDdQXZaZGKkw+SuM/IqikzqrRUPOE7jNakuvaXNWsvg2iCEQNcKKKv1Ocglj0tyrdTtBoAzU0B9rHrKL9DFypSt/krTyfFEzAvq6RVukCySMyOnFap6x4Nf3gIqBhYgw+6ehEZfIprtHNYpVNWCL7BWxnOTzqyNDVsRSMIqrIQurOoFKvo8w9CCR+o06/x6s9OYWWK/F5B1/L3zc+MMwJoCHUniFRW01Dr/Smxi7U="
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=debug msg="completed challenge"
Dec 09 06:21:04 volumio go-librespot[31936]: time="2025-12-09T06:21:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "network"...
Dec 09 06:21:05 volumio volumio[31911]: info: Refreshing Cached IP Addresses
Dec 09 06:21:05 volumio sudo[31947]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 06:21:05 volumio sudo[31947]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:05 volumio sudo[31949]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 06:21:05 volumio sudo[31947]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:05 volumio sudo[31949]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:05 volumio sudo[31949]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "services"...
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "alsa_controller"...
Dec 09 06:21:05 volumio sudo[31958]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 09 06:21:05 volumio sudo[31958]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:05 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "wizard"...
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "networkfs"...
Dec 09 06:21:05 volumio volumio[31911]: info: Starting Udev Watcher for removable devices
Dec 09 06:21:05 volumio volumio[31911]: info: Ignoring mount for partition: boot
Dec 09 06:21:05 volumio volumio[31911]: info: Ignoring mount for partition: volumio
Dec 09 06:21:05 volumio volumio[31911]: info: Ignoring mount for partition: volumio_data
Dec 09 06:21:05 volumio volumio[31911]: info: Mounting Device Wikipedia
Dec 09 06:21:05 volumio sudo[31986]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 09 06:21:05 volumio sudo[31986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:05 volumio sudo[31986]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:05 volumio volumio[31911]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 06:21:05 volumio volumio[31911]: dmesg(1) may have more information after failed mount system call.
Dec 09 06:21:05 volumio volumio[31911]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 09 06:21:05 volumio volumio[31911]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 06:21:05 volumio volumio[31911]: dmesg(1) may have more information after failed mount system call.
Dec 09 06:21:05 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "volumio_command_line_client"...
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "upnp"...
Dec 09 06:21:05 volumio volumio[31911]: info: [1765282865342] Starting Upmpd Daemon
Dec 09 06:21:05 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "my_music"...
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "mpd"...
Dec 09 06:21:05 volumio volumio-remote-updater[9752]: [2025-12-09 06:21:05] [connect] Successful connection
Dec 09 06:21:05 volumio sudo[31958]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:05 volumio volumio[31911]: info: Loading plugin "upnp_browser"...
Dec 09 06:21:07 volumio volumio[31911]: info: Loading plugin "alarm-clock"...
Dec 09 06:21:07 volumio volumio[31911]: info: Loading plugin "airplay_emulation"...
Dec 09 06:21:07 volumio volumio[31911]: info: Starting Shairport Sync
Dec 09 06:21:07 volumio volumio[31911]: info: Loading plugin "last_100"...
Dec 09 06:21:07 volumio volumio[31911]: info: Loading plugin "webradio"...
Dec 09 06:21:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8.
Dec 09 06:21:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:07 volumio volumio[31911]: info: Loading plugin "i2s_dacs"...
Dec 09 06:21:07 volumio volumio[31911]: info: I2S DAC not set, start Auto-detection
Dec 09 06:21:07 volumio volumio[31911]: info: Loading plugin "volumiodiscovery"...
Dec 09 06:21:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:07 volumio go-librespot[31991]: go-librespot daemon starting...
Dec 09 06:21:07 volumio volumio[31911]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:21:07 volumio volumio[31911]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:21:07 volumio volumio[31911]: *** WARNING *** For more information see
Dec 09 06:21:07 volumio volumio[31911]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:21:07 volumio volumio[31911]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:21:07 volumio volumio[31911]: *** WARNING *** For more information see
Dec 09 06:21:07 volumio node[31911]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:21:07 volumio node[31911]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:21:07 volumio node[31911]: *** WARNING *** For more information see
Dec 09 06:21:07 volumio node[31911]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:21:07 volumio node[31911]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:21:07 volumio node[31911]: *** WARNING *** For more information see
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=debug msg="app state loaded"
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:07 volumio volumio[31911]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:07 volumio volumio[31911]: info: Discovery: Started advertising with name: Volumio
Dec 09 06:21:07 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 06:21:07 volumio volumio[31911]: info: Loading plugin "bandcamp"...
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=info msg="zeroconf server listening on port 42437"
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=debug msg="obtained new client token: AACkG8FHIDyfr97bH/hTtTdjPACt0tRtXA1rm0WQsSR6ny36WoYSP5B99rc+sOYLizD0I3KwYzs8MiyEaRKklV9s3pZNSGGWm6qgCVqA/g2gLYXk+6VdxOZIwsJichYtRWbUTl2K1gMPpHxglIiYm1LxAtoh1DvC2rj7cuBT19LTaStQNM+8xYxjtJypcq4KICZIpfeDCrqm271nQz7QEkvgPKzMUGV3bWNvyxFand4uqqpHgKhZ1BEMxQ=="
Dec 09 06:21:07 volumio go-librespot[31992]: time="2025-12-09T06:21:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:08 volumio go-librespot[31992]: time="2025-12-09T06:21:08-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:08 volumio go-librespot[31992]: time="2025-12-09T06:21:08-06:00" level=debug msg="completed challenge"
Dec 09 06:21:08 volumio go-librespot[31992]: time="2025-12-09T06:21:08-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:08 volumio volumio[31911]: info: Plugin calmradio is not enabled
Dec 09 06:21:08 volumio volumio[31911]: info: Loading plugin "soundcloud"...
Dec 09 06:21:09 volumio volumio[31911]: info: Loading plugin "spop"...
Dec 09 06:21:10 volumio volumio[31911]: info: Loading plugin "squeezelite_mc"...
Dec 09 06:21:10 volumio volumio[31911]: info: Loading plugin "youtube2"...
Dec 09 06:21:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9.
Dec 09 06:21:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:11 volumio go-librespot[32001]: go-librespot daemon starting...
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="app state loaded"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=info msg="zeroconf server listening on port 34559"
Dec 09 06:21:11 volumio volumio[31911]: info: Loading plugin "ytcr"...
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="obtained new client token: AAAfhlKOZL3cqdeSC7oWOJUcZy+CIZ74clIwxR/L4GKkw/XPGYRDoOmRxZU+Fh8PEbn3ooczsx0aMaxSOSKdZ1gmARLcihPA7RoJRTDGJXbop4an7x8TyxEKe9xkwrhTNuXHvWa2S5beJI7g0+k49KOSJtqfs/g+tLBWnK+uLmkccSOygPM6MWEL3jqx/5tk4mwmfhorg+m01S4f4Vd5oBWQTATpEkU3+mpS2ZTX4Asd7cF4viUQtivSlA=="
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=debug msg="completed challenge"
Dec 09 06:21:11 volumio go-librespot[32002]: time="2025-12-09T06:21:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:12 volumio volumio[31911]: info: Loading plugin "ytmusic"...
Dec 09 06:21:13 volumio volumio[31911]: info: Plugin now_playing is not enabled
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "outputs"...
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "albumart"...
Dec 09 06:21:13 volumio volumio[31911]: info: Plugin example_plugin is not enabled
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "inputs"...
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "updater_comm"...
Dec 09 06:21:13 volumio volumio[31911]: info: Plugin mpdemulation is not enabled
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "rest_api"...
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "websocket"...
Dec 09 06:21:13 volumio volumio[31911]: info: Starting Socket.io Server version 1.7.4
Dec 09 06:21:13 volumio volumio[31911]: info: Plugin fusiondsp is not enabled
Dec 09 06:21:13 volumio volumio[31911]: info: Plugin mpdoutput is not enabled
Dec 09 06:21:13 volumio volumio[31911]: info: Plugin RoonBridge is not enabled
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "podcast"...
Dec 09 06:21:13 volumio volumio[31911]: info: ControllerPodcast::constructor
Dec 09 06:21:13 volumio volumio[31911]: info: Loading plugin "volusonic"...
Dec 09 06:21:14 volumio volumio[32009]: Forking 3 albumart workers
Dec 09 06:21:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10.
Dec 09 06:21:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:15 volumio go-librespot[32049]: go-librespot daemon starting...
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="app state loaded"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=info msg="zeroconf server listening on port 34967"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="obtained new client token: AAApHcm0ki4l3UErJYPLyIW1oLfAnt8wPem93MotjzzGGNxbslwOIAroARfoQe7WJmJxtTBlcw0lmNbFECtCVrchuVkJ44hqBBg95nqE5VePM9q6S/6/DhsGAGwiHwc+19rNt47URuSj9YvCcuuXBbSFrMU7g5KTHqwcE6EDej9gYcjhpbg5KvCmUmV9/SLE10cbz+1fzOfIusZe+NZQT23B4Zl0JzsEKD3j8M1QgBbVp4wJ6F+hAcIjCA=="
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=debug msg="completed challenge"
Dec 09 06:21:15 volumio volumio[31911]: info: Applying required configuration parameters for plugin volusonic
Dec 09 06:21:15 volumio volumio[31911]: info: Loading plugin "backup_restore"...
Dec 09 06:21:15 volumio go-librespot[32050]: time="2025-12-09T06:21:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:15 volumio volumio[32019]: Starting albumart workers
Dec 09 06:21:15 volumio volumio[32021]: Starting albumart workers
Dec 09 06:21:15 volumio volumio[32020]: Starting albumart workers
Dec 09 06:21:16 volumio volumio[31911]: info: Applying required configuration parameters for plugin backup_restore
Dec 09 06:21:16 volumio volumio[31911]: info: Plugin rpi_eeprom_config is not enabled
Dec 09 06:21:16 volumio volumio[31911]: info: Plugin rpi_eeprom_updater is not enabled
Dec 09 06:21:16 volumio volumio[31911]: info: Loading plugin "scheduledrestart"...
Dec 09 06:21:16 volumio volumio[31911]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 09 06:21:16 volumio volumio[31911]: info: Plugin Bluetoothremote is not enabled
Dec 09 06:21:16 volumio volumio[31911]: info: Plugin music_services_shield is not enabled
Dec 09 06:21:16 volumio volumio[31911]: info: Loading plugin "Systeminfo"...
Dec 09 06:21:16 volumio volumio[31911]: info: Plugin peppymeterbasic is not enabled
Dec 09 06:21:16 volumio volumio[31911]: info: Loading plugin "peppyspectrum"...
Dec 09 06:21:17 volumio volumio[31911]: info: Loading i18n strings for locale en
Dec 09 06:21:17 volumio volumio[31911]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 06:21:17 volumio volumio[31911]: Updating browse sources language
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::initPlayerControls
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: Express server listening on port 3000
Dec 09 06:21:17 volumio volumio[31911]: [Metrics] WebUI: 14s 817.20ms
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::resetVolumioState
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::getcurrentVolume
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:17 volumio sudo[32094]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 06:21:17 volumio sudo[32094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:17 volumio sudo[32096]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 06:21:17 volumio sudo[32096]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:17 volumio sudo[32094]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:17 volumio sudo[32096]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:17 volumio volumio[31911]: info: Volumio Network Manager: Network status updated: 1
Dec 09 06:21:17 volumio volumio[31911]: info: VolumeController:: Volume=86 Mute =false
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::pushState
Dec 09 06:21:17 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioPushState
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::updateTrackBlock
Dec 09 06:21:17 volumio volumio[31911]: info: CorePlayQueue::getTrackBlock
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 06:21:17 volumio volumio[31911]: info: Reloading queue from file
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::setRepeat null single undefined
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::pushState
Dec 09 06:21:17 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioPushState
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::setRandom null
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::pushState
Dec 09 06:21:17 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioPushState
Dec 09 06:21:17 volumio volumio[31911]: info: Setting Device type: Raspberry PI
Dec 09 06:21:17 volumio volumio[31911]: info: VolumeController:: Volume=86 Mute =false
Dec 09 06:21:17 volumio volumio[31911]: info: CoreStateMachine::pushState
Dec 09 06:21:17 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioPushState
Dec 09 06:21:17 volumio sudo[32108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 09 06:21:17 volumio sudo[32108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:17 volumio volumio[31911]: info: Completed loading Core Plugins
Dec 09 06:21:17 volumio volumio[31911]: info: Preparing to generate the ALSA configuration file
Dec 09 06:21:17 volumio volumio[31911]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 06:21:17 volumio volumio[31911]: info: Discovery: Found device Volumio
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:21:17 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:17 volumio sudo[32108]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:17 volumio volumio[31911]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 06:21:17 volumio volumio[31911]: info: Reading ALSA contributions from plugins.
Dec 09 06:21:17 volumio volumio[31911]: info: Upmpdcli Daemon Started
Dec 09 06:21:17 volumio volumio[31911]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 06:21:17 volumio volumio[31911]: info: Discovery: Found device Volumio
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:21:17 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:17 volumio volumio[31911]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 06:21:17 volumio volumio[31911]: info: Output device has changed, restarting MPD
Dec 09 06:21:17 volumio volumio[31911]: info: Output device has changed, restarting Shairport Sync
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:17 volumio sudo[32112]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 06:21:17 volumio sudo[32112]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:17 volumio sudo[32112]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:17 volumio sudo[32114]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 06:21:17 volumio sudo[32114]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:17 volumio volumio[31911]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:21:17 volumio volumio[31911]: info: ___________ START PLUGINS ___________
Dec 09 06:21:17 volumio volumio[31911]: info: ControllerMpd::onStart: Initializing MPD
Dec 09 06:21:17 volumio volumio[31911]: info: Creating MPD Configuration file
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:17 volumio volumio[31911]: info: [1765282877798] CoreMusicLibrary::Adding element Media Servers
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:17 volumio sudo[32122]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 06:21:17 volumio sudo[32122]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:17 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 09 06:21:17 volumio sudo[32122]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:17 volumio sudo[32124]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 06:21:17 volumio sudo[32124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:17 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 06:21:17 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 06:21:17 volumio systemd[1]: mpd.service: Consumed 4.476s CPU time.
Dec 09 06:21:17 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 06:21:17 volumio volumio[31911]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:17 volumio volumio[31911]: info: [1765282877911] CoreMusicLibrary::Adding element Last_100
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:17 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:17 volumio volumio[31911]: info: [1765282877916] CoreMusicLibrary::Adding element Webradio
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:17 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:21:17 volumio volumio[31911]: info: Initializing BBC Radios
Dec 09 06:21:17 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:17 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:17 volumio volumio[31911]: info: [1765282877993] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 09 06:21:17 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:17 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:18 volumio volumio[31911]: info: [1765282878005] CoreMusicLibrary::Adding element SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: info: Creating Spotify config file
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio-remote-updater[9752]: [2025-12-09 06:21:18] [connect] Successful connection
Dec 09 06:21:18 volumio sudo[32149]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 06:21:18 volumio sudo[32149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 06:21:18 volumio sudo[32149]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:18 volumio volumio[31911]: info: [squeezelite_mc] Starting proxy server...
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:18 volumio volumio[31911]: info: [1765282878370] CoreMusicLibrary::Adding element YouTube2
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube2
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:18 volumio volumio[31911]: info: [1765282878390] CoreMusicLibrary::Adding element YouTube Music
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube2
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube Music
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:18 volumio volumio[31911]: info: [1765282878402] CoreMusicLibrary::Adding element Podcast
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube2
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube Music
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Podcast
Dec 09 06:21:18 volumio volumio[31911]: info: Loading i18n strings for locale en
Dec 09 06:21:18 volumio volumio[31911]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 06:21:18 volumio volumio[31911]: Updating browse sources language
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube2
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube Music
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Podcast
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube2
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube Music
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Podcast
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:18 volumio volumio[31911]: info: [1765282878457] CoreMusicLibrary::Adding element Volusonic
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube2
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source YouTube Music
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Podcast
Dec 09 06:21:18 volumio volumio[31911]: Cannot find translation for source Volusonic
Dec 09 06:21:18 volumio volumio[31911]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 09 06:21:18 volumio volumio[31911]: info: Volumio Calling Home
Dec 09 06:21:18 volumio volumio[31911]: info: [squeezelite_mc] Proxy server started on port 46669
Dec 09 06:21:18 volumio volumio[31911]: info: Preparing to generate the ALSA configuration file
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 06:21:18 volumio volumio[31911]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 06:21:18 volumio volumio[31911]: info: Reading ALSA contributions from plugins.
Dec 09 06:21:18 volumio volumio[31911]: info: MPD Permissions set
Dec 09 06:21:18 volumio volumio[31911]: info: MPD Permissions set
Dec 09 06:21:18 volumio volumio-remote-updater[9752]: [2025-12-09 06:21:18] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765282878 101
Dec 09 06:21:18 volumio volumio[31911]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1
Dec 09 06:21:18 volumio volumio[31911]: info: Spotify config file written
Dec 09 06:21:18 volumio sudo[32160]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 09 06:21:18 volumio sudo[32160]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:18 volumio volumio[31911]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2
Dec 09 06:21:18 volumio volumio[31911]: info: VolumeController:: Volume=86 Mute =false
Dec 09 06:21:18 volumio volumio[31911]: info: CoreStateMachine::pushState
Dec 09 06:21:18 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::volumioPushState
Dec 09 06:21:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11.
Dec 09 06:21:18 volumio volumio[31911]: info: [squeezelite_mc] Server discovery started
Dec 09 06:21:18 volumio volumio[31911]: info: [squeezelite_mc] Player finder started
Dec 09 06:21:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio go-librespot[32162]: go-librespot daemon starting...
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio sudo[32160]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:18 volumio volumio[31911]: info: No need to fix Spotify hosts
Dec 09 06:21:18 volumio go-librespot[32170]: time="2025-12-09T06:21:18-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:18-06:00" level=debug msg="app state loaded"
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:18-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:19 volumio volumio[31911]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3
Dec 09 06:21:19 volumio volumio[31911]: info: Volumio called home
Dec 09 06:21:19 volumio volumio[31911]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=info msg="zeroconf server listening on port 33077"
Dec 09 06:21:19 volumio volumio[31911]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 09 06:21:19 volumio volumio[31911]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 09 06:21:19 volumio volumio[31911]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=debug msg="obtained new client token: AAD0PIriHN/SIwYxfxRVdoTjltMzSR3vH7b7GN4Y89XfP2ir99o6x8urDZltv1BF8dnkO0NndlCRpuPwHuEQIpXPj/nnS5wWuVxmKd1pfgdVqSjPKgFk6K7ys03p4KAOzYZHwlix/v+Xx7+ndhBTHvL55MA/s5vGP31x4ltmVbNEXfapuhxXSEBgyP7A3ab4RwRpvCShJMYim02VeS7dUgpHCT8dEq2ixoeJOzzUwLeTnENKZNybtD+5Og=="
Dec 09 06:21:19 volumio volumio[31911]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 06:21:19 volumio volumio[31911]: SPOTIFY: BQDKPbu0ZVdMxeDR0aTOulsQxztvizmS-wODEk3p0p8bdinQnr6gMVts05KHUU1Vlxl2YXCG5k5i6vZB6x0z4GYxwCZW1us6Ij6zXmjJCqbzg1ub2hw9-emzxjjIfplHqbh7wL9vcvrG1itlUBgvocg1XCXYGsHRanv7YYMIlv45JFS_x__IKKwuLakTeiH530m9BLmsJ8bgg971wYrman0wZPzprYm_MpMOgu8
Dec 09 06:21:19 volumio volumio[31911]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 06:21:19 volumio volumio[31911]: info: New Spotify access token = BQDKPbu0ZVdMxeDR0aTOulsQxztvizmS-wODEk3p0p8bdinQnr6gMVts05KHUU1Vlxl2YXCG5k5i6vZB6x0z4GYxwCZW1us6Ij6zXmjJCqbzg1ub2hw9-emzxjjIfplHqbh7wL9vcvrG1itlUBgvocg1XCXYGsHRanv7YYMIlv45JFS_x__IKKwuLakTeiH530m9BLmsJ8bgg971wYrman0wZPzprYm_MpMOgu8
Dec 09 06:21:19 volumio volumio[31911]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 09 06:21:19 volumio volumio[31911]: info: Starting Shairport Sync
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:19 volumio volumio[31911]: info: Starting Shairport Sync
Dec 09 06:21:19 volumio volumio[31911]: info: Starting Shairport Sync
Dec 09 06:21:19 volumio sudo[32188]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:21:19 volumio sudo[32188]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=debug msg="completed challenge"
Dec 09 06:21:19 volumio sudo[32190]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:21:19 volumio sudo[32185]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 09 06:21:19 volumio sudo[32185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:19 volumio sudo[32190]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:19 volumio sudo[32185]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:19 volumio sudo[32193]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:21:19 volumio sudo[32193]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:19 volumio go-librespot[32170]: time="2025-12-09T06:21:19-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:19 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 06:21:19 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 06:21:19 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:21:19 volumio systemd[1]: shairport-sync.service: Consumed 1.860s CPU time.
Dec 09 06:21:19 volumio volumio[31911]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 09 06:21:19 volumio volumio[31911]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 06:21:19 volumio volumio[31911]: info: Output device has changed, restarting MPD
Dec 09 06:21:19 volumio sudo[32202]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 09 06:21:19 volumio volumio[31911]: info: Output device has changed, restarting Shairport Sync
Dec 09 06:21:19 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:19 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:19 volumio sudo[32202]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:19 volumio sudo[32202]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:19 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:21:19 volumio sudo[32204]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 06:21:19 volumio sudo[32204]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:19 volumio sudo[32188]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:19 volumio sudo[32204]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:19 volumio sudo[32190]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:19 volumio sudo[32208]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 06:21:19 volumio sudo[32208]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:19 volumio sudo[32193]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:19 volumio volumio[31911]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:21:19 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 06:21:19 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 06:21:19 volumio systemd[1]: mpd.service: Consumed 1.730s CPU time.
Dec 09 06:21:19 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 06:21:19 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 06:21:19 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 06:21:19 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 06:21:19 volumio volumio[31911]: info: MPD Permissions set
Dec 09 06:21:19 volumio volumio[31911]: info: Shairport-Sync Started
Dec 09 06:21:19 volumio volumio[31911]: Error adding Membership: Error: addMembership EINVAL
Dec 09 06:21:19 volumio volumio[31911]: info: Shairport-Sync Started
Dec 09 06:21:19 volumio volumio[31911]: info: Shairport-Sync Started
Dec 09 06:21:19 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 06:21:19 volumio volumio[31911]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:21:20 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:20 volumio sudo[32235]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 09 06:21:20 volumio sudo[32235]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:20 volumio sudo[32235]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:20 volumio volumio[31911]: info: Starting Shairport Sync
Dec 09 06:21:20 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true
Dec 09 06:21:20 volumio sudo[32243]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:21:20 volumio sudo[32243]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:20 volumio volumio[31911]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"}
Dec 09 06:21:20 volumio volumio[31911]: info: Spotify Successfully logged in
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:21:20 volumio volumio[31911]: info: [1765282880231] CoreMusicLibrary::Adding element Spotify
Dec 09 06:21:20 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:21:20 volumio volumio[31911]: Cannot find translation for source Bandcamp Discover
Dec 09 06:21:20 volumio volumio[31911]: Cannot find translation for source SoundCloud
Dec 09 06:21:20 volumio volumio[31911]: Cannot find translation for source YouTube2
Dec 09 06:21:20 volumio volumio[31911]: Cannot find translation for source YouTube Music
Dec 09 06:21:20 volumio volumio[31911]: Cannot find translation for source Podcast
Dec 09 06:21:20 volumio volumio[31911]: Cannot find translation for source Volusonic
Dec 09 06:21:20 volumio volumio[31911]: Cannot find translation for source Spotify
Dec 09 06:21:20 volumio sudo[32232]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 06:21:20 volumio sudo[32232]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 06:21:20 volumio sudo[32246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 09 06:21:20 volumio sudo[32246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:20 volumio sudo[32232]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:20 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 06:21:20 volumio systemd[1]: Reloading.
Dec 09 06:21:20 volumio volumio[31911]: info: [squeezelite_mc] Notification listener started
Dec 09 06:21:20 volumio volumio[31911]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 06:21:20 volumio volumio[31911]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 06:21:20 volumio volumio[31911]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 06:21:21 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:21 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:21 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:21 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:21:22 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:21:22 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:22 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:22 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:22 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 06:21:22 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:21:22 volumio sudo[32246]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:22 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:21:22 volumio sudo[32269]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:21:22 volumio sudo[32269]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:22 volumio volumio[31911]: info: go-librespot daemon successfully initialized
Dec 09 06:21:22 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:21:22 volumio sudo[32243]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:22 volumio volumio[31911]: info: Shairport-Sync Started
Dec 09 06:21:22 volumio sudo[32269]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:22 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 09 06:21:22 volumio sudo[32285]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 09 06:21:22 volumio sudo[32285]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:22 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 06:21:22 volumio volumio[31911]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 09 06:21:22 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:21:22 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12.
Dec 09 06:21:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:22 volumio go-librespot[32288]: go-librespot daemon starting...
Dec 09 06:21:22 volumio go-librespot[32289]: time="2025-12-09T06:21:22-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:22 volumio go-librespot[32289]: time="2025-12-09T06:21:22-06:00" level=debug msg="app state loaded"
Dec 09 06:21:22 volumio go-librespot[32289]: time="2025-12-09T06:21:22-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:22 volumio go-librespot[32289]: time="2025-12-09T06:21:22-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:22 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 09 06:21:22 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 06:21:22 volumio sudo[32285]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=info msg="zeroconf server listening on port 36351"
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=debug msg="obtained new client token: AAA6194C+95BLQoVll9ZMv99F9IzUdXc3rBJO6tFkzi8LDp3Q20OF0Be79R2xKdWP19zuZ66tUwfa18h23PTy6wEJV49C8mfTmM9OPlK9YWNSUJj4YLbEeuZtGWs2zc2uckHeOAvhAXRmh5ZYRuiAVo7c7aUfejb+tZoQgfx8EryPpk9B9tElPbzt4a3zFNDdvcxDRZGvGwVhj+i8RloNLvuz9SbYqNIcX33RknROmAGcfsZj7+8bhk="
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=debug msg="completed challenge"
Dec 09 06:21:23 volumio go-librespot[32289]: time="2025-12-09T06:21:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:23 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:21:23 volumio sudo[32298]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:21:23 volumio sudo[32298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:23 volumio sudo[32298]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:23 volumio volumio[31911]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 09 06:21:23 volumio sudo[32302]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 09 06:21:23 volumio sudo[32302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:23 volumio sudo[32302]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:23 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 09 06:21:23 volumio sudo[32305]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 09 06:21:23 volumio sudo[32305]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:23 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 06:21:23 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 06:21:23 volumio sudo[32305]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:23 volumio volumio[31911]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 09 06:21:23 volumio volumio[31911]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 06:21:23 volumio volumio[31911]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 06:21:23 volumio volumio[31911]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 06:21:23 volumio mpd[32249]: 2025-12-09T06:21:23 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 09 06:21:24 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 09 06:21:24 volumio sudo[32124]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:24 volumio sudo[32114]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:24 volumio sudo[32208]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:24 volumio volumio[31911]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 06:21:24 volumio volumio[31911]: assert.ok(self.idling)
Dec 09 06:21:24 volumio volumio[31911]: error: The expression evaluated to a falsy value:
Dec 09 06:21:24 volumio volumio[31911]: assert.ok(self.idling)
Dec 09 06:21:24 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:21:24 volumio volumio[31911]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 06:21:24 volumio volumio[31911]: assert.ok(self.idling)
Dec 09 06:21:24 volumio volumio[31911]: error: The expression evaluated to a falsy value:
Dec 09 06:21:24 volumio volumio[31911]: assert.ok(self.idling)
Dec 09 06:21:24 volumio volumio[31911]: info: MPD running with PID32249
Dec 09 06:21:24 volumio volumio[31911]: ,establishing connection
Dec 09 06:21:24 volumio volumio[31911]: error: updateQueue error: null
Dec 09 06:21:24 volumio volumio[31911]: error: updateQueue error: null
Dec 09 06:21:24 volumio sudo[32316]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:21:24 volumio sudo[32316]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:24 volumio sudo[32316]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:24 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:21:24 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:21:24 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:24 volumio sudo[32319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:21:24 volumio sudo[32319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:25 volumio sudo[32319]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:25 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:25 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:25 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:21:25 volumio sudo[32336]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:21:25 volumio sudo[32336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:25 volumio sudo[32336]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:26 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:21:26 volumio sudo[32342]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:21:26 volumio sudo[32342]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:26 volumio sudo[32342]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13.
Dec 09 06:21:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:26 volumio go-librespot[32344]: go-librespot daemon starting...
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="app state loaded"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:26 volumio volumio[31911]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:21:26 volumio sudo[32353]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21: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-gew4.spotify.com:80]"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:26 volumio sudo[32353]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=info msg="zeroconf server listening on port 43035"
Dec 09 06:21:26 volumio sudo[32353]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:26 volumio volumio[31911]: info: Completed starting Core Plugins
Dec 09 06:21:26 volumio volumio[31911]: info: -------------------------------------------
Dec 09 06:21:26 volumio volumio[31911]: info: ----- MyVolumio plugins startup ----
Dec 09 06:21:26 volumio volumio[31911]: info: -------------------------------------------
Dec 09 06:21:26 volumio volumio[31911]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="obtained new client token: AADk82oKoQv0U7kj48CRS6mwjvTkxHOVOHMZw/OV6veyO6K0q5mGTTPp3oWJiuXmwW8Zdi0iWn9hov/KcXGozerlgrSq84o061lO2BI2e4dtMpRGYG58aJKU44F/I06VyuMmAkPbMRKeeFPE1Pb32O7M81uqPSIm85Hw9Z0hwqTtJSSB9G5RWlVAKJydr0gpVhbzoqUG/U4z5hH8FqlgSCRjL2Y+2t8YrsI/BGV0e55QtN84sOzbu7PIFg=="
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=debug msg="completed challenge"
Dec 09 06:21:26 volumio go-librespot[32345]: time="2025-12-09T06:21:26-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:27 volumio sudo[32356]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 06:21:27 volumio sudo[32356]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:27 volumio sudo[32359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 06:21:27 volumio sudo[32359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:27 volumio sudo[32361]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 06:21:27 volumio sudo[32361]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:27 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 09 06:21:27 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 09 06:21:27 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 09 06:21:27 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 09 06:21:27 volumio sudo[32361]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:27 volumio sudo[32359]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:27 volumio sudo[32356]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:27 volumio mpd_monitor.sh[32364]: MPD Monitor Service: Starting MPD Monitor Service
Dec 09 06:21:27 volumio volumio[31911]: info: Successfully started MPD Monitor
Dec 09 06:21:27 volumio volumio[31911]: info: Successfully started MPD Monitor
Dec 09 06:21:27 volumio volumio[31911]: info: Successfully started MPD Monitor
Dec 09 06:21:28 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:28 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14.
Dec 09 06:21:30 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:30 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:30 volumio go-librespot[32368]: go-librespot daemon starting...
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=debug msg="app state loaded"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21: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]"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21: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]"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21: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]"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=info msg="zeroconf server listening on port 35665"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=debug msg="obtained new client token: AAAteHr1YdBgqJT5fELq5Q0HE5n+jRlYj8JR1TXcjvXh65VlP3xGtTn7OGqEEcmYFVkxBqI9b+IemWLikSIN4hd1zkUALZPTFnLiNTK4JtBIE4ipqigQxKmrHHeRQmOcjdAbbKC7YYvppp52As2zbWfhPfbn7KaB+bV3tr5S+s3LZPJvu8N/Qohhs4iIkVqxCYFzkRyybjTen6CGO3ZWeJRsZjWrKy3KT71hV0DO+gSo94VTYrLEd5s0cw=="
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=debug msg="completed challenge"
Dec 09 06:21:30 volumio go-librespot[32369]: time="2025-12-09T06:21:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:32 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:32 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15.
Dec 09 06:21:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:33 volumio go-librespot[32376]: go-librespot daemon starting...
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=debug msg="app state loaded"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21: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]"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21: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]"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21: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]"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=info msg="zeroconf server listening on port 34911"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=debug msg="obtained new client token: AAAd0DIi7wFsWlNPEt5T3i2kmrMOb1mqbQr8jvaTRXTSmhlFAoF1hhK6VElE9RnwBwJLoTfzfoJ0i3ad0Q0p6Aooa8EUt/ykhf9+yzOb3B4zOzk7+aOd6gQmFG+hrQn0Kjs1reG4fdWPiJeew32MtzssDxEEk2G8pXNQ/3uIjkF2FdJJp9eeCtA/Io7xftn+3MnS+pCxVYkj36Byz0q0Wia+HJsw97UfngO8OVyWbkaVlXxKnVO4dghSXg=="
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=debug msg="completed challenge"
Dec 09 06:21:34 volumio go-librespot[32377]: time="2025-12-09T06:21:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 09 06:21:35 volumio volumio[31911]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 09 06:21:35 volumio volumio[31911]: info: Adding plugin multiroom to MyMusic Plugins
Dec 09 06:21:35 volumio volumio[31911]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 09 06:21:35 volumio volumio[31911]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 09 06:21:35 volumio volumio[31911]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 09 06:21:35 volumio volumio[31911]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 09 06:21:35 volumio volumio[31911]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 09 06:21:35 volumio volumio[31911]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 09 06:21:35 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:35 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:35 volumio volumio[31911]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 09 06:21:36 volumio volumio[31911]: info: MyVolumio login type: Token
Dec 09 06:21:36 volumio volumio[31911]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 09 06:21:36 volumio volumio[31911]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 09 06:21:36 volumio volumio[31911]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 09 06:21:36 volumio volumio[31911]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 09 06:21:36 volumio volumio[31911]: info: Streaming services startup
Dec 09 06:21:36 volumio volumio[31911]: info: Starting Streaming Daemon
Dec 09 06:21:36 volumio sudo[32399]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 06:21:36 volumio sudo[32399]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:36 volumio volumio[31911]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 09 06:21:36 volumio sudo[32399]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:36 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:36 volumio volumio[31911]: error: Cannot start Volumio Streaming Daemon
Dec 09 06:21:36 volumio volumio[31911]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 06:21:36 volumio volumio[31911]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 06:21:37 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:37 volumio volumio[31911]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 09 06:21:37 volumio volumio[31911]: info: MyVolumio token set successfully
Dec 09 06:21:37 volumio volumio[31911]: info: MYVOLUMIO: Adding device
Dec 09 06:21:37 volumio volumio[31911]: info: MYVOLUMIO: Evaluating Server
Dec 09 06:21:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16.
Dec 09 06:21:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:37 volumio go-librespot[32409]: go-librespot daemon starting...
Dec 09 06:21:37 volumio go-librespot[32415]: time="2025-12-09T06:21:37-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:37 volumio go-librespot[32415]: time="2025-12-09T06:21:37-06:00" level=debug msg="app state loaded"
Dec 09 06:21:37 volumio go-librespot[32415]: time="2025-12-09T06:21:37-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:37 volumio go-librespot[32415]: time="2025-12-09T06:21:37-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:37 volumio volumio[31911]: info: MyVolumio status changed
Dec 09 06:21:37 volumio volumio[31911]: info: Streaming services startup
Dec 09 06:21:37 volumio volumio[31911]: info: Starting Streaming Daemon
Dec 09 06:21:37 volumio volumio[31911]: info: Removing browser output: myVolumio user plan is not superstar
Dec 09 06:21:37 volumio volumio[31911]: info: Removing audio output:
Dec 09 06:21:37 volumio volumio[31911]: info: Stoppping Tunnel 1
Dec 09 06:21:37 volumio sudo[32436]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 06:21:37 volumio sudo[32436]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:37 volumio sudo[32438]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 09 06:21:37 volumio sudo[32438]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:21:38 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:38 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:38 volumio sudo[32436]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:38 volumio volumio[31911]: error: Cannot start Volumio Streaming Daemon
Dec 09 06:21:38 volumio volumio[31911]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 06:21:38 volumio volumio[31911]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 06:21:38 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:38 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:38 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:38 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:21:38 volumio sudo[32438]: pam_unix(sudo:session): session closed for user root
Dec 09 06:21:38 volumio volumio[31911]: info: Remote SSH Stopped
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=info msg="zeroconf server listening on port 44081"
Dec 09 06:21:38 volumio volumio[31911]: info: Setting Geolocation for MyVolumio to us1
Dec 09 06:21:38 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:38 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:38 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=debug msg="obtained new client token: AAC0uFvC3FtPvY4z5Hho5WTs2UK+88xqrPGTEnMvGE9Fm9rqNdGDGXiXnhYA0prj+rBwozdQHfNYlU9ONoVqGpHaaK0pdyw2ggfoV4X/ykS8jRyD55JA5ZRe4k1nPH2Rq0JqYnCMJr0PVZ50HWOLnM791blD1B20Su0Fj2Cw6UIrsEmgIK7d6F4paWARepOa3zVuvNG25bTaZFnTLRbVfp3n/jlCtZG2jj9LvETboFhPLyKV/0HmG80="
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=debug msg="completed challenge"
Dec 09 06:21:38 volumio volumio[31911]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 06:21:38 volumio go-librespot[32415]: time="2025-12-09T06:21:38-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:39 volumio volumio[31911]: info: Updating MyVolumio device info
Dec 09 06:21:39 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:39 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:39 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:39 volumio volumio[31911]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 06:21:40 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:40 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17.
Dec 09 06:21:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:41 volumio go-librespot[32441]: go-librespot daemon starting...
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="app state loaded"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=info msg="zeroconf server listening on port 38035"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="obtained new client token: AACumFxawLiq5/+ddU27J2d1ygUoYPwf/FzUR0Rr0/QxGEJbiG6YlVAi3WaCY2xh2fICpQKnEJE3HMBVglHPHy07n9du2rwGb8RkmZYuewYStyAZdKxKCEEPOW/icR8d/gbn7N2j+NEl3ym2pfB7c/YJnY9QKpa0myCbCFlDKKs+TDYzTl3766lWrHbTf3c1SjtCMkpr3zyw5vGoqvy8k2NpnjN+XKQV7n8ByrRdp2b5tFCOx75/QdE9Kg=="
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=debug msg="completed challenge"
Dec 09 06:21:41 volumio go-librespot[32442]: time="2025-12-09T06:21:41-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:42 volumio volumio[31911]: info: MYVOLUMIO: Adding device
Dec 09 06:21:42 volumio volumio[31911]: info: MYVOLUMIO: Evaluating Server
Dec 09 06:21:42 volumio volumio[31911]: info: Setting Geolocation for MyVolumio to us4
Dec 09 06:21:42 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:42 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:42 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:42 volumio volumio[31911]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 06:21:43 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:43 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:43 volumio volumio[31911]: info: Updating MyVolumio device info
Dec 09 06:21:43 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:43 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:43 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:44 volumio volumio[31911]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 06:21:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18.
Dec 09 06:21:45 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:45 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:45 volumio go-librespot[32467]: go-librespot daemon starting...
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="app state loaded"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=info msg="zeroconf server listening on port 37167"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="obtained new client token: AADWePdEbmvHRXlVTOx+wyeVG7lj+IEIVYjI8f/7576gjDpBss9KLKXUFEKqX8MtIUxeWWM6OunNTkb0ENqc9bH6hFYJgYHkwfvaLnGK1SOsGrppgILXRep8LNe/U4SAsMvHF/fnBjzXoa/V3MLT4p8eZh9fp1IX2Kzr/GB7KRLomfbgdEGIXSFyXGtbIgPjpNRxcDS6F2GyoHzKiHtRbnfb3QN6pv+U9bKzV07lr5VvWYK4Ftm9XoWJnQ=="
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=debug msg="completed challenge"
Dec 09 06:21:45 volumio go-librespot[32468]: time="2025-12-09T06:21:45-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:46 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:46 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:48 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:21:48 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:48 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 09 06:21:48 volumio volumio-remote-updater[9752]: Test mode disabled
Dec 09 06:21:48 volumio volumio-remote-updater[9752]: Alpha mode disabled
Dec 09 06:21:48 volumio volumio-remote-updater[9752]: Alpha legacy test mode disabled
Dec 09 06:21:48 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 09 06:21:48 volumio volumio[31911]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"ANNOUNCEMENT
\n\n- Production line
\n
\nFIX
\n\n- Nodejs 20.5.1 version pinning with static package fallback
\n
\n","title":"Update v4.073","updateavailable":true}
Dec 09 06:21:48 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 09 06:21:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19.
Dec 09 06:21:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:49 volumio go-librespot[32497]: go-librespot daemon starting...
Dec 09 06:21:49 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:49 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="app state loaded"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=info msg="zeroconf server listening on port 40885"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="obtained new client token: AAC8rWC6/4LodQ6zlxfJKssTSiim06AjwkFN2mKayPCFbe3GQC8unUs2biyjkqVKaJlx9956pcGizLLd7z/jmoiO5H9oNyJIXiyKCYRRtBqrbTh+8lQGMugZfLzdYdZNmztnD23gMZbhoEfe0eqaoBjUtzlX78glEmQFX86Qd1JeGfWMXvQBQSQDP2pjEbsCR1mLdQrMiehcxHwsY4VvqaH6y1Hvu0o9+/9PWNRVyo9Z8ZqXxtIwBgRtTg=="
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=debug msg="completed challenge"
Dec 09 06:21:49 volumio go-librespot[32498]: time="2025-12-09T06:21:49-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:50 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 09 06:21:51 volumio volumio[31911]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4
Dec 09 06:21:51 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:21:51 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:21:52 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:52 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20.
Dec 09 06:21:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:52 volumio go-librespot[32505]: go-librespot daemon starting...
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=debug msg="app state loaded"
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:21:52 volumio go-librespot[32506]: time="2025-12-09T06:21:52-06:00" level=info msg="zeroconf server listening on port 43819"
Dec 09 06:21:53 volumio go-librespot[32506]: time="2025-12-09T06:21:53-06:00" level=debug msg="obtained new client token: AAALQGncPz58STP6xnBsmMqudjqKJg/zyS3B5LLCVKd8eytucda2UOlgVkxtMr78iXGOzECkfiwOirJXtcTsEZSdqM8LHntcCsz/KqxYFYbnXdOLmMZZkIKJGId/Cy3UK3+DHHqKGRvimOUX8ORFqwRvvbfrhOG0BskvdFTvOUifjVU3VchwYdB3fNQLHG5gbGdqYvfzH+O4ARZ95E4C9/tsvJJfQxCwKced0gfw198RoNxhHHS2G5U="
Dec 09 06:21:53 volumio go-librespot[32506]: time="2025-12-09T06:21:53-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:21:53 volumio go-librespot[32506]: time="2025-12-09T06:21:53-06:00" level=debug msg="completed keyexchange"
Dec 09 06:21:53 volumio go-librespot[32506]: time="2025-12-09T06:21:53-06:00" level=debug msg="completed challenge"
Dec 09 06:21:53 volumio go-librespot[32506]: time="2025-12-09T06:21:53-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:21:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:21:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:21:55 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:55 volumio volumio[31911]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:21:55 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:55 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:55 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Dec 09 06:21:55 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 09 06:21:55 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Dec 09 06:21:56 volumio volumio[31911]: info: CoreCommandRouter::volumioGetBrowseSources
Dec 09 06:21:56 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:21:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21.
Dec 09 06:21:56 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:56 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:21:56 volumio go-librespot[32527]: go-librespot daemon starting...
Dec 09 06:21:56 volumio go-librespot[32528]: time="2025-12-09T06:21:56-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:21:56 volumio go-librespot[32528]: time="2025-12-09T06:21:56-06:00" level=debug msg="app state loaded"
Dec 09 06:21:56 volumio go-librespot[32528]: time="2025-12-09T06:21:56-06:00" level=debug msg="stored credentials not found"
Dec 09 06:21:56 volumio go-librespot[32528]: time="2025-12-09T06:21:56-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:21:56 volumio volumio[31911]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Dec 09 06:21:56 volumio volumio[31911]: info: Completed starting MyVolumio Plugin
Dec 09 06:21:56 volumio volumio[31911]: [Metrics] CommandRouter: 53s 980.21ms
Dec 09 06:21:56 volumio volumio[31911]: info: CoreCommandRouter::volumiosetStartupVolume
Dec 09 06:21:56 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:21:56 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:21:56 volumio volumio[31911]: info: CoreCommandRouter::Close All Modals sent
Dec 09 06:21:56 volumio volumio[31911]: info: CoreCommandRouter::Close All Modals sent
Dec 09 06:21:57 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Dec 09 06:21:57 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Dec 09 06:21:58 volumio volumio[31911]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Dec 09 06:21:58 volumio volumio[31911]: info: Initializing connection to go-librespot Websocket
Dec 09 06:21:58 volumio go-librespot[32528]: time="2025-12-09T06:21:58-06:00" level=debug msg="new websocket client"
Dec 09 06:21:58 volumio volumio[31911]: info: Connection to go-librespot Websocket established
Dec 09 06:22:01 volumio volumio[31911]: info: Getting Spotify volume
Dec 09 06:22:01 volumio volumio[31911]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5
Dec 09 06:22:01 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:01 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:01 volumio volumio[31911]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86
Dec 09 06:22:01 volumio volumio[31911]: SPOTIFY: SPOTIFY VOLUME undefined
Dec 09 06:22:01 volumio volumio[31911]: SPOTIFY: VOLUMIO VOLUME 86
Dec 09 06:22:01 volumio volumio[31911]: info: Aligning Spotify Volume to Volumio Volume
Dec 09 06:22:01 volumio volumio[31911]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:01 volumio volumio[31911]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:01 volumio volumio[31911]: info: Setting Spotify Volume from Volumio: 86
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=info msg="zeroconf server listening on port 40611"
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=debug msg="obtained new client token: AADbL2zfag+LYuO2Uq7ccinqf7vVDg68Cj8E04uT7qI9IGm3+4HOjfWTPMEyILpPtugDG+cOFyfLwz7sGtsa7h/XD3qDNEeYoLgY8y0PfcQ9BjDn1HD9wxlXIA8Siy13qFduYWAAs1VfDCEe1LhPo41PbOlkgSgwIP6sFruGTadxkN2h1RP1oh19Gc6hPiEI96c0fawsN1uuMk76qJqreRScCOXaTd25+NGfDDG3GkINrxR5xgHodx8Uvg=="
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:01 volumio go-librespot[32528]: time="2025-12-09T06:22:01-06:00" level=debug msg="completed challenge"
Dec 09 06:22:02 volumio go-librespot[32528]: time="2025-12-09T06:22:02-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:02 volumio volumio[31911]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 06:22:02 volumio volumio[31911]: Error: socket hang up
Dec 09 06:22:02 volumio volumio[31911]: at connResetException (node:internal/errors:720:14)
Dec 09 06:22:02 volumio volumio[31911]: at Socket.socketOnEnd (node:_http_client:519:23)
Dec 09 06:22:02 volumio volumio[31911]: at Socket.emit (node:events:526:35)
Dec 09 06:22:02 volumio volumio[31911]: at endReadableNT (node:internal/streams/readable:1376:12)
Dec 09 06:22:02 volumio volumio[31911]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 09 06:22:02 volumio volumio[31911]: code: 'ECONNRESET',
Dec 09 06:22:02 volumio volumio[31911]: response: undefined
Dec 09 06:22:02 volumio volumio[31911]: }
Dec 09 06:22:02 volumio volumio[31911]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 06:22:02 volumio sudo[32555]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 06:21'
Dec 09 06:22:02 volumio sudo[32555]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:02 volumio sudo[32555]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:03 volumio volumio-remote-updater[9752]: [2025-12-09 06:22:03] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 09 06:22:03 volumio volumio-remote-updater[9752]: [2025-12-09 06:22:03] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 09 06:22:03 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:03 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 09 06:22:03 volumio systemd[1]: volumio.service: Consumed 50.158s CPU time.
Dec 09 06:22:03 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 06:22:03 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 06:22:03 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 24143.
Dec 09 06:22:03 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 09 06:22:03 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 09 06:22:03 volumio systemd[1]: volumio.service: Consumed 50.158s CPU time.
Dec 09 06:22:03 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 09 06:22:03 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 09 06:22:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22.
Dec 09 06:22:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:05 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:05 volumio go-librespot[32590]: go-librespot daemon starting...
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="app state loaded"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=info msg="zeroconf server listening on port 46625"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="obtained new client token: AADD+KdVbQjJ0AvlsYcHEPLPs5yG079TaD5xeBGCHSEEG3zBjJAInVitk7E3MIWZ8wGDE3NRpRUontxgJ7kNKVAlX2ZWEH381HEeQpXFf6hTHFHL/voMBpaJBBKM5KTJcFR9iKrY5UyJnV9EWun7GBpuROea9LKR7gNyat9nQDPWrLjuJr2F5SSx1QTGwKb9q3FZipWUtoWdyToH3ivTkl2ALmeAdZUBNcQj+zb4LM8NorIK013d1gsBMA=="
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=debug msg="completed challenge"
Dec 09 06:22:05 volumio go-librespot[32591]: time="2025-12-09T06:22:05-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:05 volumio volumio[32575]: info: -------------------------------------------
Dec 09 06:22:05 volumio volumio[32575]: info: ----- Volumio3 ----
Dec 09 06:22:05 volumio volumio[32575]: info: -------------------------------------------
Dec 09 06:22:05 volumio volumio[32575]: info: ----- System startup ----
Dec 09 06:22:05 volumio volumio[32575]: info: -------------------------------------------
Dec 09 06:22:06 volumio volumio[32575]: info: MYVOLUMIO Environment detected
Dec 09 06:22:06 volumio volumio[32575]: info: Plugin folders cleanup
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning into folder /volumio/app/plugins/
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category audio_interface
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category miscellanea
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category music_service
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category plugins.json
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category system_controller
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category user_interface
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning into folder /data/plugins/
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category audio_interface
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category music_service
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category system_controller
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category system_hardware
Dec 09 06:22:06 volumio volumio[32575]: info: Scanning category user_interface
Dec 09 06:22:06 volumio volumio[32575]: info: Plugin folders cleanup completed
Dec 09 06:22:06 volumio volumio[32575]: info: -------------------------------------------
Dec 09 06:22:06 volumio volumio[32575]: info: ----- Core plugins startup ----
Dec 09 06:22:06 volumio volumio[32575]: info: -------------------------------------------
Dec 09 06:22:06 volumio volumio[32575]: info: Loading plugins from folder /volumio/app/plugins/
Dec 09 06:22:06 volumio volumio[32575]: info: Adding plugin upnp to MyMusic Plugins
Dec 09 06:22:06 volumio volumio[32575]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 09 06:22:06 volumio volumio[32575]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 09 06:22:06 volumio volumio[32575]: info: Loading plugins from folder /data/plugins/
Dec 09 06:22:06 volumio volumio[32575]: info: Loading plugin "system"...
Dec 09 06:22:06 volumio volumio[32575]: info: Loading plugin "appearance"...
Dec 09 06:22:07 volumio volumio[32575]: info: Loading plugin "network"...
Dec 09 06:22:07 volumio volumio[32575]: info: Refreshing Cached IP Addresses
Dec 09 06:22:08 volumio sudo[32615]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 06:22:08 volumio sudo[32615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:08 volumio sudo[32615]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:08 volumio sudo[32617]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 06:22:08 volumio sudo[32617]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:08 volumio sudo[32617]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "services"...
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "alsa_controller"...
Dec 09 06:22:08 volumio sudo[32625]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 09 06:22:08 volumio sudo[32625]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:08 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "wizard"...
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "networkfs"...
Dec 09 06:22:08 volumio volumio[32575]: info: Starting Udev Watcher for removable devices
Dec 09 06:22:08 volumio volumio[32575]: info: Ignoring mount for partition: boot
Dec 09 06:22:08 volumio volumio[32575]: info: Ignoring mount for partition: volumio
Dec 09 06:22:08 volumio volumio[32575]: info: Ignoring mount for partition: volumio_data
Dec 09 06:22:08 volumio volumio[32575]: info: Mounting Device Wikipedia
Dec 09 06:22:08 volumio sudo[32654]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 09 06:22:08 volumio sudo[32654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:08 volumio sudo[32654]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:08 volumio volumio[32575]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 06:22:08 volumio volumio[32575]: dmesg(1) may have more information after failed mount system call.
Dec 09 06:22:08 volumio volumio[32575]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 09 06:22:08 volumio volumio[32575]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 09 06:22:08 volumio volumio[32575]: dmesg(1) may have more information after failed mount system call.
Dec 09 06:22:08 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "volumio_command_line_client"...
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "upnp"...
Dec 09 06:22:08 volumio volumio[32575]: info: [1765282928282] Starting Upmpd Daemon
Dec 09 06:22:08 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "my_music"...
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "mpd"...
Dec 09 06:22:08 volumio sudo[32625]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:08 volumio volumio[32575]: info: Loading plugin "upnp_browser"...
Dec 09 06:22:08 volumio volumio-remote-updater[9752]: [2025-12-09 06:22:08] [connect] Successful connection
Dec 09 06:22:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23.
Dec 09 06:22:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:08 volumio go-librespot[32656]: go-librespot daemon starting...
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="app state loaded"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=info msg="zeroconf server listening on port 46479"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="obtained new client token: AAD5VFtH1zEa4et5FguVSxycwmxRrL2HjS/07KnXgY+q8eNl9sYE8kM6hgOmGG1lh/59tyzQwVpGSOWXLUSkj8+AkMv9dEHORZja+xSqIMIRlFofagXe4R/LGx9nteRB9/RIjasP+qdm2YnUj4ROWPhkJa9ZNwb2zeAAsG7qjLXN7LqXw4bGKukqKsDjonkToXQOCFOmrnDY5MG0kDoeSQXRh5n+h1hDSbrOyZDgOI3znMn981+8AYqWCw=="
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=debug msg="completed challenge"
Dec 09 06:22:09 volumio go-librespot[32657]: time="2025-12-09T06:22:09-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:10 volumio volumio[32575]: info: Loading plugin "alarm-clock"...
Dec 09 06:22:10 volumio volumio[32575]: info: Loading plugin "airplay_emulation"...
Dec 09 06:22:10 volumio volumio[32575]: info: Starting Shairport Sync
Dec 09 06:22:10 volumio volumio[32575]: info: Loading plugin "last_100"...
Dec 09 06:22:10 volumio volumio[32575]: info: Loading plugin "webradio"...
Dec 09 06:22:10 volumio volumio[32575]: info: Loading plugin "i2s_dacs"...
Dec 09 06:22:10 volumio volumio[32575]: info: I2S DAC not set, start Auto-detection
Dec 09 06:22:10 volumio volumio[32575]: info: Loading plugin "volumiodiscovery"...
Dec 09 06:22:10 volumio volumio[32575]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:22:10 volumio volumio[32575]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:22:10 volumio volumio[32575]: *** WARNING *** For more information see
Dec 09 06:22:10 volumio volumio[32575]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:22:10 volumio volumio[32575]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:22:10 volumio volumio[32575]: *** WARNING *** For more information see
Dec 09 06:22:10 volumio node[32575]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:22:10 volumio node[32575]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:22:10 volumio node[32575]: *** WARNING *** For more information see
Dec 09 06:22:10 volumio node[32575]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 09 06:22:10 volumio node[32575]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 09 06:22:10 volumio node[32575]: *** WARNING *** For more information see
Dec 09 06:22:10 volumio volumio[32575]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 09 06:22:10 volumio volumio[32575]: info: Discovery: Started advertising with name: Volumio
Dec 09 06:22:10 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 09 06:22:10 volumio volumio[32575]: info: Loading plugin "bandcamp"...
Dec 09 06:22:11 volumio volumio[32575]: info: Plugin calmradio is not enabled
Dec 09 06:22:11 volumio volumio[32575]: info: Loading plugin "soundcloud"...
Dec 09 06:22:12 volumio volumio[32575]: info: Loading plugin "spop"...
Dec 09 06:22:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24.
Dec 09 06:22:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:12 volumio go-librespot[32667]: go-librespot daemon starting...
Dec 09 06:22:12 volumio go-librespot[32668]: time="2025-12-09T06:22:12-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:12 volumio go-librespot[32668]: time="2025-12-09T06:22:12-06:00" level=debug msg="app state loaded"
Dec 09 06:22:12 volumio go-librespot[32668]: time="2025-12-09T06:22:12-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:12 volumio go-librespot[32668]: time="2025-12-09T06:22:12-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=info msg="zeroconf server listening on port 45417"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=debug msg="obtained new client token: AAB/lfxztm4jYeC/RgobTcEEfru8ah6UHulYO9r0Z4RdSPHv9+ceGYsLdG5viKXCqCMItauWa8BGIB4meiIuA7R0/3hUFEjbh7EG5j/hwwo6wMYM8OZYCNofkcIOkg9I4atIzpkdblLWZOWga3pp2seESKoHIY4i1RYXfgFBLeVy86AGB7o7fA/9hNlcQ2qBOCgVrtbN0NzegOkxmRNlAeO/L2BvwkIzWZlnjjcUBXoQx8X18JTLEaU="
Dec 09 06:22:13 volumio volumio[32575]: info: Loading plugin "squeezelite_mc"...
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:443"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=debug msg="completed challenge"
Dec 09 06:22:13 volumio go-librespot[32668]: time="2025-12-09T06:22:13-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:13 volumio volumio[32575]: info: Loading plugin "youtube2"...
Dec 09 06:22:14 volumio volumio[32575]: info: Loading plugin "ytcr"...
Dec 09 06:22:15 volumio volumio[32575]: info: Loading plugin "ytmusic"...
Dec 09 06:22:16 volumio volumio[32575]: info: Plugin now_playing is not enabled
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "outputs"...
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "albumart"...
Dec 09 06:22:16 volumio volumio[32575]: info: Plugin example_plugin is not enabled
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "inputs"...
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "updater_comm"...
Dec 09 06:22:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25.
Dec 09 06:22:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:16 volumio volumio[32575]: info: Plugin mpdemulation is not enabled
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "rest_api"...
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "websocket"...
Dec 09 06:22:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:16 volumio go-librespot[32684]: go-librespot daemon starting...
Dec 09 06:22:16 volumio volumio[32575]: info: Starting Socket.io Server version 1.7.4
Dec 09 06:22:16 volumio volumio[32575]: info: Plugin fusiondsp is not enabled
Dec 09 06:22:16 volumio volumio[32575]: info: Plugin mpdoutput is not enabled
Dec 09 06:22:16 volumio volumio[32575]: info: Plugin RoonBridge is not enabled
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "podcast"...
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=debug msg="app state loaded"
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:16 volumio volumio[32575]: info: ControllerPodcast::constructor
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=info msg="zeroconf server listening on port 40995"
Dec 09 06:22:16 volumio volumio[32575]: info: Loading plugin "volusonic"...
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=debug msg="obtained new client token: AAArIA23MvHygtgQH9NLMiwV60ZtrrS5463Ah9zwOW1fecA5hDRra4irJ3rY3Wj4AWeOX3G4QYDeV+1j7ecSrhxOdDT4XWQRJwVf+pEnUoYg8Ygr8peLrsuZSJ7omWCEROgZZ6IKuEO/AszS1119hh4lP2qeAKBmCNfsQKisl3ZrCkKzMIhOOJ4GJnXjiHmMqbfLFALo/ZK8kPzAN0OEFaeJXcxnA1l1PNKFLBONQswBvH9q3WRPmQg24w=="
Dec 09 06:22:16 volumio volumio[32675]: Forking 3 albumart workers
Dec 09 06:22:16 volumio go-librespot[32686]: time="2025-12-09T06:22:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:17 volumio go-librespot[32686]: time="2025-12-09T06:22:17-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:17 volumio go-librespot[32686]: time="2025-12-09T06:22:17-06:00" level=debug msg="completed challenge"
Dec 09 06:22:17 volumio go-librespot[32686]: time="2025-12-09T06:22:17-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:18 volumio volumio[32575]: info: Applying required configuration parameters for plugin volusonic
Dec 09 06:22:18 volumio volumio[32575]: info: Loading plugin "backup_restore"...
Dec 09 06:22:18 volumio volumio[32694]: Starting albumart workers
Dec 09 06:22:18 volumio volumio[32695]: Starting albumart workers
Dec 09 06:22:18 volumio volumio[32693]: Starting albumart workers
Dec 09 06:22:18 volumio volumio[32575]: info: Applying required configuration parameters for plugin backup_restore
Dec 09 06:22:18 volumio volumio[32575]: info: Plugin rpi_eeprom_config is not enabled
Dec 09 06:22:18 volumio volumio[32575]: info: Plugin rpi_eeprom_updater is not enabled
Dec 09 06:22:18 volumio volumio[32575]: info: Loading plugin "scheduledrestart"...
Dec 09 06:22:19 volumio volumio[32575]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 09 06:22:19 volumio volumio[32575]: info: Plugin Bluetoothremote is not enabled
Dec 09 06:22:19 volumio volumio[32575]: info: Plugin music_services_shield is not enabled
Dec 09 06:22:19 volumio volumio[32575]: info: Loading plugin "Systeminfo"...
Dec 09 06:22:19 volumio volumio[32575]: info: Plugin peppymeterbasic is not enabled
Dec 09 06:22:19 volumio volumio[32575]: info: Loading plugin "peppyspectrum"...
Dec 09 06:22:19 volumio volumio[32575]: info: Loading i18n strings for locale en
Dec 09 06:22:19 volumio volumio[32575]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 06:22:19 volumio volumio[32575]: Updating browse sources language
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::initPlayerControls
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:22:19 volumio volumio[32575]: Express server listening on port 3000
Dec 09 06:22:19 volumio volumio[32575]: [Metrics] WebUI: 14s 536.64ms
Dec 09 06:22:19 volumio volumio[32575]: info: CoreStateMachine::resetVolumioState
Dec 09 06:22:19 volumio volumio[32575]: info: CoreStateMachine::getcurrentVolume
Dec 09 06:22:19 volumio volumio[32575]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:20 volumio sudo[32760]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 06:22:20 volumio sudo[32760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:20 volumio sudo[32760]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:20 volumio sudo[32762]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 06:22:20 volumio sudo[32762]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:20 volumio sudo[32762]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:20 volumio volumio[32575]: info: Volumio Network Manager: Network status updated: 1
Dec 09 06:22:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26.
Dec 09 06:22:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:20 volumio volumio[32575]: info: VolumeController:: Volume=86 Mute =false
Dec 09 06:22:20 volumio volumio[32575]: info: CoreStateMachine::pushState
Dec 09 06:22:20 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioPushState
Dec 09 06:22:20 volumio volumio[32575]: info: CoreStateMachine::updateTrackBlock
Dec 09 06:22:20 volumio volumio[32575]: info: CorePlayQueue::getTrackBlock
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 06:22:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:20 volumio go-librespot[32767]: go-librespot daemon starting...
Dec 09 06:22:20 volumio volumio[32575]: info: Reloading queue from file
Dec 09 06:22:20 volumio volumio[32575]: info: CoreStateMachine::setRepeat null single undefined
Dec 09 06:22:20 volumio volumio[32575]: info: CoreStateMachine::pushState
Dec 09 06:22:20 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioPushState
Dec 09 06:22:20 volumio volumio[32575]: info: CoreStateMachine::setRandom null
Dec 09 06:22:20 volumio volumio[32575]: info: CoreStateMachine::pushState
Dec 09 06:22:20 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioPushState
Dec 09 06:22:20 volumio volumio[32575]: info: Setting Device type: Raspberry PI
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="app state loaded"
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:20 volumio volumio[32575]: info: VolumeController:: Volume=86 Mute =false
Dec 09 06:22:20 volumio volumio[32575]: info: CoreStateMachine::pushState
Dec 09 06:22:20 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioPushState
Dec 09 06:22:20 volumio sudo[319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 09 06:22:20 volumio volumio[32575]: info: Completed loading Core Plugins
Dec 09 06:22:20 volumio sudo[319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:20 volumio volumio[32575]: info: Preparing to generate the ALSA configuration file
Dec 09 06:22:20 volumio volumio[32575]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 06:22:20 volumio volumio[32575]: info: Discovery: Found device Volumio
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:20 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:20 volumio sudo[319]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:20 volumio volumio[32575]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954
Dec 09 06:22:20 volumio volumio[32575]: info: Discovery: Found device Volumio
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:20 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:20 volumio volumio[32575]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 06:22:20 volumio volumio[32575]: info: Reading ALSA contributions from plugins.
Dec 09 06:22:20 volumio volumio[32575]: info: Upmpdcli Daemon Started
Dec 09 06:22:20 volumio volumio[32575]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 06:22:20 volumio volumio[32575]: info: Output device has changed, restarting MPD
Dec 09 06:22:20 volumio volumio[32575]: info: Output device has changed, restarting Shairport Sync
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:20 volumio sudo[324]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 06:22:20 volumio sudo[324]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:20 volumio sudo[324]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:20 volumio sudo[326]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 06:22:20 volumio sudo[326]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:20 volumio volumio[32575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:22:20 volumio volumio[32575]: info: ___________ START PLUGINS ___________
Dec 09 06:22:20 volumio volumio[32575]: info: ControllerMpd::onStart: Initializing MPD
Dec 09 06:22:20 volumio volumio[32575]: info: Creating MPD Configuration file
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:20 volumio volumio[32575]: info: [1765282940574] CoreMusicLibrary::Adding element Media Servers
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 09 06:22:20 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 09 06:22:20 volumio sudo[334]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 06:22:20 volumio sudo[334]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=info msg="zeroconf server listening on port 36559"
Dec 09 06:22:20 volumio sudo[334]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:20 volumio sudo[336]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 06:22:20 volumio sudo[336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:20 volumio volumio[32575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:20 volumio volumio[32575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:20 volumio volumio[32575]: info: [1765282940699] CoreMusicLibrary::Adding element Last_100
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:20 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 06:22:20 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 06:22:20 volumio systemd[1]: mpd.service: Consumed 4.560s CPU time.
Dec 09 06:22:20 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:20 volumio volumio[32575]: info: [1765282940708] CoreMusicLibrary::Adding element Webradio
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:20 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 06:22:20 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="obtained new client token: AADBppWDGkMaD6F8L8LjGei82Pya5rbhVGp6vi23SfyP6qphTF/F3whap5jBZaL2w/J2g4YVjWjnsPDB3I4HvakFXd53m97Y+jIxSkUi+m4AUBZB/uxDD3fmGddXJhJYdl+OtDSYblt+0MXjjQuuR+Lh3gPzsikVHHq8Q8hHf6b0+/kYxLgJ+bHFCZQn7izu3FqOnmx8bZdSP9gqtDTlZs9/hN+RaWxE/ciL1k4ahdzSXBCh4k6SuhwOFg=="
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:22:20 volumio volumio[32575]: info: Initializing BBC Radios
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:20 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:20 volumio volumio[32575]: info: [1765282940788] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:20 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 06:22:20 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:20 volumio volumio[32575]: info: [1765282940804] CoreMusicLibrary::Adding element SoundCloud
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:20 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:20 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:20 volumio volumio[32575]: info: Creating Spotify config file
Dec 09 06:22:20 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=debug msg="completed challenge"
Dec 09 06:22:20 volumio go-librespot[307]: time="2025-12-09T06:22:20-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:21 volumio sudo[363]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 06:22:21 volumio sudo[363]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 06:22:21 volumio sudo[363]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:21 volumio volumio[32575]: info: [squeezelite_mc] Starting proxy server...
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:21 volumio volumio[32575]: info: [1765282941175] CoreMusicLibrary::Adding element YouTube2
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube2
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:21 volumio volumio[32575]: info: [1765282941193] CoreMusicLibrary::Adding element YouTube Music
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube2
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube Music
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:21 volumio volumio[32575]: info: [1765282941206] CoreMusicLibrary::Adding element Podcast
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube2
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube Music
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Podcast
Dec 09 06:22:21 volumio volumio[32575]: info: Loading i18n strings for locale en
Dec 09 06:22:21 volumio volumio[32575]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 09 06:22:21 volumio volumio[32575]: Updating browse sources language
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube2
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube Music
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Podcast
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube2
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube Music
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Podcast
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:21 volumio volumio[32575]: info: [1765282941254] CoreMusicLibrary::Adding element Volusonic
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube2
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source YouTube Music
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Podcast
Dec 09 06:22:21 volumio volumio[32575]: Cannot find translation for source Volusonic
Dec 09 06:22:21 volumio volumio-remote-updater[9752]: [2025-12-09 06:22:21] [connect] Successful connection
Dec 09 06:22:21 volumio volumio[32575]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 09 06:22:21 volumio volumio[32575]: info: Volumio Calling Home
Dec 09 06:22:21 volumio volumio[32575]: info: [squeezelite_mc] Proxy server started on port 35877
Dec 09 06:22:21 volumio volumio[32575]: info: Preparing to generate the ALSA configuration file
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::volumioRetrievevolume
Dec 09 06:22:21 volumio volumio[32575]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 09 06:22:21 volumio volumio[32575]: info: Reading ALSA contributions from plugins.
Dec 09 06:22:21 volumio volumio[32575]: info: MPD Permissions set
Dec 09 06:22:21 volumio volumio[32575]: info: MPD Permissions set
Dec 09 06:22:21 volumio volumio-remote-updater[9752]: [2025-12-09 06:22:21] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765282941 101
Dec 09 06:22:21 volumio volumio[32575]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1
Dec 09 06:22:21 volumio volumio[32575]: info: Spotify config file written
Dec 09 06:22:21 volumio sudo[373]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 09 06:22:21 volumio sudo[373]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:21 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:21 volumio volumio[32575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2
Dec 09 06:22:21 volumio volumio[32575]: info: VolumeController:: Volume=86 Mute =false
Dec 09 06:22:21 volumio volumio[32575]: info: CoreStateMachine::pushState
Dec 09 06:22:21 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::volumioPushState
Dec 09 06:22:21 volumio volumio[32575]: info: [squeezelite_mc] Server discovery started
Dec 09 06:22:21 volumio volumio[32575]: info: [squeezelite_mc] Player finder started
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true
Dec 09 06:22:21 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:21 volumio go-librespot[375]: go-librespot daemon starting...
Dec 09 06:22:21 volumio sudo[373]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio go-librespot[376]: time="2025-12-09T06:22:21-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:21 volumio go-librespot[376]: time="2025-12-09T06:22:21-06:00" level=debug msg="app state loaded"
Dec 09 06:22:21 volumio go-librespot[376]: time="2025-12-09T06:22:21-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio go-librespot[376]: time="2025-12-09T06:22:21-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:21 volumio volumio[32575]: info: No need to fix Spotify hosts
Dec 09 06:22:22 volumio volumio[32575]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3
Dec 09 06:22:22 volumio volumio[32575]: info: Volumio called home
Dec 09 06:22:22 volumio volumio[32575]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}
Dec 09 06:22:22 volumio volumio[32575]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 09 06:22:22 volumio volumio[32575]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 09 06:22:22 volumio volumio[32575]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=info msg="zeroconf server listening on port 34701"
Dec 09 06:22:22 volumio volumio[32575]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 06:22:22 volumio volumio[32575]: SPOTIFY: BQAe1GdKc0DGh82wdIUmzBxymh0nzJgR6WyyeiUoAcAN7f73s__KLR2aqLYxOjJ90YiN7o5bxfyjUEZMQi1r2GVXx5jnf5U5x9Mks9NlWlbrKU_z5jkcnzbANMBSycehkyZZvk-RrxWOyGoOlbeGLHL_gnfFGl3C_r7BqQm4s8_o2W2pdRixQMItBQF7_F7bgd1EwLAxqQmfwsMA55auxT8mzRrjSI-n4b37AIE
Dec 09 06:22:22 volumio volumio[32575]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 09 06:22:22 volumio volumio[32575]: info: New Spotify access token = BQAe1GdKc0DGh82wdIUmzBxymh0nzJgR6WyyeiUoAcAN7f73s__KLR2aqLYxOjJ90YiN7o5bxfyjUEZMQi1r2GVXx5jnf5U5x9Mks9NlWlbrKU_z5jkcnzbANMBSycehkyZZvk-RrxWOyGoOlbeGLHL_gnfFGl3C_r7BqQm4s8_o2W2pdRixQMItBQF7_F7bgd1EwLAxqQmfwsMA55auxT8mzRrjSI-n4b37AIE
Dec 09 06:22:22 volumio volumio[32575]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=debug msg="obtained new client token: AADPxPOM2zyAVndPQ6Q+q73bAF+5cq6jrna8h7Ddd1Yd61pQbiJvRgbCI4IGDDoDqyHnokuwEy1l4rrc+DU+Xffz/hVMwCKDu2H0Lr3j4ZKVwkvoxL22tNIY4e/pq3C8K8QFnA4h2kS7yHtIvWIXyoYikNRf67waZ2OCax4uFvORlTbj14d1wCKubkqMm4dZyadoYu4eO//RVZXHQF/n/RsMf3RG9S5fxQnAOSFVD5q9qLlykqwgSYo="
Dec 09 06:22:22 volumio volumio[32575]: info: Starting Shairport Sync
Dec 09 06:22:22 volumio volumio[32575]: info: Starting Shairport Sync
Dec 09 06:22:22 volumio volumio[32575]: info: Starting Shairport Sync
Dec 09 06:22:22 volumio sudo[401]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 09 06:22:22 volumio sudo[404]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:22:22 volumio sudo[401]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio sudo[404]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:22 volumio sudo[406]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:22:22 volumio sudo[401]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:22 volumio sudo[406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio sudo[408]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:22:22 volumio sudo[408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=debug msg="completed challenge"
Dec 09 06:22:22 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 06:22:22 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 06:22:22 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:22:22 volumio systemd[1]: shairport-sync.service: Consumed 2.074s CPU time.
Dec 09 06:22:22 volumio volumio[32575]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 09 06:22:22 volumio go-librespot[376]: time="2025-12-09T06:22:22-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:22 volumio volumio[32575]: info: Asound.conf file unchanged, so no further update is needed
Dec 09 06:22:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:22 volumio volumio[32575]: info: Output device has changed, restarting MPD
Dec 09 06:22:22 volumio sudo[415]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 09 06:22:22 volumio sudo[415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio sudo[417]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 09 06:22:22 volumio sudo[415]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:22 volumio sudo[417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio volumio[32575]: info: Output device has changed, restarting Shairport Sync
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:22 volumio sudo[417]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:22 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:22:22 volumio sudo[422]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 09 06:22:22 volumio sudo[422]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio sudo[404]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:22 volumio volumio[32575]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 09 06:22:22 volumio sudo[408]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:22 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 06:22:22 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 06:22:22 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:22:22 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 09 06:22:22 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 09 06:22:22 volumio systemd[1]: mpd.service: Consumed 1.613s CPU time.
Dec 09 06:22:22 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 09 06:22:22 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 09 06:22:22 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 09 06:22:22 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 09 06:22:22 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 09 06:22:22 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:22:22 volumio sudo[406]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:22 volumio volumio[32575]: info: MPD Permissions set
Dec 09 06:22:22 volumio volumio[32575]: info: Shairport-Sync Started
Dec 09 06:22:22 volumio volumio[32575]: Error adding Membership: Error: addMembership EINVAL
Dec 09 06:22:22 volumio volumio[32575]: info: Shairport-Sync Started
Dec 09 06:22:22 volumio volumio[32575]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 09 06:22:22 volumio volumio[32575]: info: Shairport-Sync Started
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio sudo[438]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 09 06:22:22 volumio sudo[438]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:22 volumio sudo[438]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:22 volumio volumio[32575]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"}
Dec 09 06:22:22 volumio sudo[433]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 09 06:22:22 volumio volumio[32575]: info: Spotify Successfully logged in
Dec 09 06:22:22 volumio sudo[433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 09 06:22:22 volumio volumio[32575]: info: [1765282942986] CoreMusicLibrary::Adding element Spotify
Dec 09 06:22:22 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 06:22:22 volumio volumio[32575]: Cannot find translation for source Bandcamp Discover
Dec 09 06:22:22 volumio volumio[32575]: Cannot find translation for source SoundCloud
Dec 09 06:22:22 volumio volumio[32575]: Cannot find translation for source YouTube2
Dec 09 06:22:22 volumio volumio[32575]: Cannot find translation for source YouTube Music
Dec 09 06:22:22 volumio volumio[32575]: Cannot find translation for source Podcast
Dec 09 06:22:22 volumio volumio[32575]: Cannot find translation for source Volusonic
Dec 09 06:22:22 volumio volumio[32575]: Cannot find translation for source Spotify
Dec 09 06:22:22 volumio sudo[433]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:23 volumio volumio[32575]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:23 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:23 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true
Dec 09 06:22:23 volumio sudo[462]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 09 06:22:23 volumio sudo[462]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:23 volumio volumio[32575]: info: Starting Shairport Sync
Dec 09 06:22:23 volumio systemd[1]: Reloading.
Dec 09 06:22:23 volumio sudo[466]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 09 06:22:23 volumio sudo[466]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:23 volumio volumio[32575]: info: [squeezelite_mc] Notification listener started
Dec 09 06:22:23 volumio volumio[32575]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 06:22:23 volumio volumio[32575]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 06:22:23 volumio volumio[32575]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 06:22:24 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:24 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:24 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 09 06:22:24 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 09 06:22:25 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:25 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:25 volumio volumio[32575]: info: go-librespot daemon successfully initialized
Dec 09 06:22:25 volumio volumio[32575]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:25 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:25 volumio sudo[462]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:25 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:22:25 volumio sudo[486]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:22:25 volumio sudo[486]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 09 06:22:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 09 06:22:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:22:25 volumio systemd[1]: shairport-sync.service: Consumed 1.482s CPU time.
Dec 09 06:22:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 09 06:22:25 volumio sudo[466]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:25 volumio volumio[32575]: info: Shairport-Sync Started
Dec 09 06:22:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27.
Dec 09 06:22:25 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:25 volumio sudo[486]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:25 volumio go-librespot[510]: go-librespot daemon starting...
Dec 09 06:22:25 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=debug msg="app state loaded"
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:25 volumio sudo[518]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 09 06:22:25 volumio sudo[518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:25 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 06:22:25 volumio volumio[32575]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 09 06:22:25 volumio volumio[32575]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:25 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:25 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 09 06:22:25 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=info msg="zeroconf server listening on port 36043"
Dec 09 06:22:25 volumio sudo[518]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:25 volumio go-librespot[511]: time="2025-12-09T06:22:25-06:00" level=debug msg="obtained new client token: AAC485+NAQJ7kP7JOwhE+N84WSc5fifm1zVh6xqON1DrMLFOcy+920u6av1PS8XpTOBlE+1wEwKHOZROt6+U3noa5s0kuSy3wXOjm8QmCLsHowmRJpzEOGoTEfixU+KTFn5ShV6cN5DzSC4Ih09EVbP5R2orpMvrBZJ2Mo6F0XU2LKhYa8UF6CA+6vW/4BupM/GYyt8BDoeJ6WxNL8ioQJ9X06wSXXliINi6rgDIRMphRglRcarnvReiIQ=="
Dec 09 06:22:26 volumio go-librespot[511]: time="2025-12-09T06:22:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:26 volumio go-librespot[511]: time="2025-12-09T06:22:26-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:26 volumio go-librespot[511]: time="2025-12-09T06:22:26-06:00" level=debug msg="completed challenge"
Dec 09 06:22:26 volumio go-librespot[511]: time="2025-12-09T06:22:26-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:26 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:22:26 volumio sudo[523]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:22:26 volumio sudo[523]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:26 volumio sudo[523]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:26 volumio volumio[32575]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 09 06:22:26 volumio sudo[527]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 09 06:22:26 volumio sudo[527]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:26 volumio sudo[527]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:26 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 09 06:22:26 volumio sudo[530]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 09 06:22:26 volumio sudo[530]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:26 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 09 06:22:26 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 09 06:22:26 volumio sudo[530]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:26 volumio volumio[32575]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 09 06:22:26 volumio volumio[32575]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 09 06:22:26 volumio mpd[460]: 2025-12-09T06:22:26 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 09 06:22:26 volumio volumio[32575]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 09 06:22:26 volumio volumio[32575]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 09 06:22:27 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 09 06:22:27 volumio sudo[326]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:27 volumio sudo[422]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:27 volumio sudo[336]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:27 volumio volumio[32575]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 06:22:27 volumio volumio[32575]: assert.ok(self.idling)
Dec 09 06:22:27 volumio volumio[32575]: error: The expression evaluated to a falsy value:
Dec 09 06:22:27 volumio volumio[32575]: assert.ok(self.idling)
Dec 09 06:22:27 volumio volumio[32575]: error: MPD error: The expression evaluated to a falsy value:
Dec 09 06:22:27 volumio volumio[32575]: assert.ok(self.idling)
Dec 09 06:22:27 volumio volumio[32575]: error: The expression evaluated to a falsy value:
Dec 09 06:22:27 volumio volumio[32575]: assert.ok(self.idling)
Dec 09 06:22:27 volumio volumio[32575]: info: MPD running with PID460
Dec 09 06:22:27 volumio volumio[32575]: ,establishing connection
Dec 09 06:22:27 volumio volumio[32575]: error: updateQueue error: null
Dec 09 06:22:27 volumio volumio[32575]: error: updateQueue error: null
Dec 09 06:22:27 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:22:27 volumio sudo[541]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:22:27 volumio sudo[541]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:27 volumio sudo[541]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:27 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:22:27 volumio sudo[548]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:22:27 volumio sudo[548]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:27 volumio sudo[548]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:27 volumio volumio[32575]: info: CoreCommandRouter::volumioGetState
Dec 09 06:22:27 volumio volumio[32575]: info: CorePlayQueue::getTrack 0
Dec 09 06:22:28 volumio volumio[32575]: info: Initializing connection to go-librespot Websocket
Dec 09 06:22:28 volumio volumio[32575]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:22:28 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:22:28 volumio sudo[565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:22:28 volumio sudo[565]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:28 volumio sudo[565]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:29 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:22:29 volumio sudo[568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:22:29 volumio sudo[568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:29 volumio sudo[568]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28.
Dec 09 06:22:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:29 volumio go-librespot[570]: go-librespot daemon starting...
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="app state loaded"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=info msg="zeroconf server listening on port 46585"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="obtained new client token: AAA+yvrMfn+rDWeahCgOgj+S3IPUH4f5K4DBgChflhsmHTRgwrwD8hmPUHlZPbn43GCHiixiEhXLdXv7J135uzEFoVnGpAkWDb3oERenVh3gDYpRLzcRvL9lwlPgIQZOd9vhMU+uGY99RoJrInM22g+ZQ2Q9z1+plAHuHberz0CRuRwpLUMw+dBH8ngOFrWPE8kXwxdvF+0jfpTJJTWMyqM1J4nHPw2UWWtUerntUVbBvBf1+blmiMtImw=="
Dec 09 06:22:29 volumio volumio[32575]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 09 06:22:29 volumio sudo[580]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 09 06:22:29 volumio sudo[580]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:29 volumio sudo[580]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:29 volumio volumio[32575]: info: Completed starting Core Plugins
Dec 09 06:22:29 volumio volumio[32575]: info: -------------------------------------------
Dec 09 06:22:29 volumio volumio[32575]: info: ----- MyVolumio plugins startup ----
Dec 09 06:22:29 volumio volumio[32575]: info: -------------------------------------------
Dec 09 06:22:29 volumio volumio[32575]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:29 volumio go-librespot[571]: time="2025-12-09T06:22:29-06:00" level=debug msg="completed challenge"
Dec 09 06:22:30 volumio sudo[583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 06:22:30 volumio sudo[583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:30 volumio sudo[585]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 06:22:30 volumio sudo[585]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:30 volumio sudo[588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 09 06:22:30 volumio sudo[588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:30 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 09 06:22:30 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 09 06:22:30 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 09 06:22:30 volumio go-librespot[571]: time="2025-12-09T06:22:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:30 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 09 06:22:30 volumio sudo[583]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:30 volumio sudo[585]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:30 volumio sudo[588]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:30 volumio volumio[32575]: info: Successfully started MPD Monitor
Dec 09 06:22:30 volumio mpd_monitor.sh[591]: MPD Monitor Service: Starting MPD Monitor Service
Dec 09 06:22:30 volumio volumio[32575]: info: Successfully started MPD Monitor
Dec 09 06:22:30 volumio volumio[32575]: info: Successfully started MPD Monitor
Dec 09 06:22:31 volumio volumio[32575]: info: Initializing connection to go-librespot Websocket
Dec 09 06:22:31 volumio volumio[32575]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:22:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29.
Dec 09 06:22:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:33 volumio go-librespot[596]: go-librespot daemon starting...
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=debug msg="app state loaded"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=info msg="zeroconf server listening on port 37223"
Dec 09 06:22:33 volumio go-librespot[597]: time="2025-12-09T06:22:33-06:00" level=debug msg="obtained new client token: AADr2ZjfCcPG4JoSfrt18BR/YVHCqMyMWxIZy6eP3G75zaw0j1Es5+AExANHSUuRcMMOXxqU8H81o5I20Iwpq01BftMBLEm6N9ZigMNnfeEfA/RO4xljMvY4HVHtaucsDYw8xZFAG4zDIg75OhhB/0jmAW54X5afO7rxfJHKGCzQQinLTNJ/6sCLH60IjPmN+E4UZE37ccWjnoBo9Of9RGo1wKAvkNUrEF80mxqHELHy1plbNE0lm9isew=="
Dec 09 06:22:34 volumio go-librespot[597]: time="2025-12-09T06:22:34-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused"
Dec 09 06:22:34 volumio go-librespot[597]: time="2025-12-09T06:22:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:443"
Dec 09 06:22:34 volumio go-librespot[597]: time="2025-12-09T06:22:34-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:34 volumio go-librespot[597]: time="2025-12-09T06:22:34-06:00" level=debug msg="completed challenge"
Dec 09 06:22:34 volumio go-librespot[597]: time="2025-12-09T06:22:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:34 volumio volumio[32575]: info: Initializing connection to go-librespot Websocket
Dec 09 06:22:34 volumio volumio[32575]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:22:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30.
Dec 09 06:22:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:37 volumio go-librespot[604]: go-librespot daemon starting...
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="app state loaded"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=info msg="zeroconf server listening on port 36439"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="obtained new client token: AADGlPrxYbNKS1cwlCzalTTCV1XongEr+sb75g4lt0E8MehmeyYV5Vx6HXyyYJcBk9cR4SHrBU1qAkX1sxIqRU7UIJIszi5q7IgwLouqdaariGfrjKpjaFz3fif+2LAxx5fJRNpAxSpy+xHEROUE3lEtUAgxaLFVin1jmOme6XYycbrGa/C4m9bLO4KA+LQUpntk6KnK7UD9JijpUV6uNdKuKBw8CZ7Py2gOKoL7Y0rX+UM4FfvrySvtjQ=="
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22:37-06:00" level=debug msg="completed challenge"
Dec 09 06:22:37 volumio go-librespot[605]: time="2025-12-09T06:22: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 "
Dec 09 06:22:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 09 06:22:37 volumio volumio[32575]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 09 06:22:37 volumio volumio[32575]: info: Adding plugin multiroom to MyMusic Plugins
Dec 09 06:22:37 volumio volumio[32575]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 09 06:22:37 volumio volumio[32575]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 09 06:22:37 volumio volumio[32575]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 09 06:22:37 volumio volumio[32575]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 09 06:22:37 volumio volumio[32575]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 09 06:22:37 volumio volumio[32575]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 09 06:22:38 volumio volumio[32575]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 09 06:22:38 volumio volumio[32575]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 09 06:22:38 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:38 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:38 volumio volumio[32575]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 09 06:22:38 volumio volumio[32575]: info: MyVolumio login type: Token
Dec 09 06:22:38 volumio volumio[32575]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 09 06:22:38 volumio volumio[32575]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 09 06:22:39 volumio volumio[32575]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 09 06:22:39 volumio volumio[32575]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 09 06:22:39 volumio volumio[32575]: info: Streaming services startup
Dec 09 06:22:39 volumio volumio[32575]: info: Starting Streaming Daemon
Dec 09 06:22:39 volumio sudo[627]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 06:22:39 volumio sudo[627]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:39 volumio volumio[32575]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 09 06:22:39 volumio sudo[627]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:39 volumio volumio[32575]: info: Initializing connection to go-librespot Websocket
Dec 09 06:22:39 volumio volumio[32575]: error: Cannot start Volumio Streaming Daemon
Dec 09 06:22:39 volumio volumio[32575]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 06:22:39 volumio volumio[32575]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 06:22:39 volumio volumio[32575]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:22:40 volumio volumio[32575]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 09 06:22:40 volumio volumio[32575]: info: MyVolumio token set successfully
Dec 09 06:22:40 volumio volumio[32575]: info: MYVOLUMIO: Adding device
Dec 09 06:22:40 volumio volumio[32575]: info: MYVOLUMIO: Evaluating Server
Dec 09 06:22:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31.
Dec 09 06:22:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:41 volumio go-librespot[645]: go-librespot daemon starting...
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="app state loaded"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:41 volumio volumio[32575]: info: MyVolumio status changed
Dec 09 06:22:41 volumio volumio[32575]: info: Streaming services startup
Dec 09 06:22:41 volumio volumio[32575]: info: Starting Streaming Daemon
Dec 09 06:22:41 volumio volumio[32575]: info: Removing browser output: myVolumio user plan is not superstar
Dec 09 06:22:41 volumio volumio[32575]: info: Removing audio output:
Dec 09 06:22:41 volumio volumio[32575]: info: Stoppping Tunnel 1
Dec 09 06:22:41 volumio sudo[666]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 09 06:22:41 volumio sudo[666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:41 volumio sudo[668]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 09 06:22:41 volumio sudo[668]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:41 volumio sudo[666]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:41 volumio volumio[32575]: error: Cannot start Volumio Streaming Daemon
Dec 09 06:22:41 volumio volumio[32575]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 09 06:22:41 volumio volumio[32575]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 09 06:22:41 volumio sudo[668]: pam_unix(sudo:session): session closed for user root
Dec 09 06:22:41 volumio volumio[32575]: info: Remote SSH Stopped
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=info msg="zeroconf server listening on port 44899"
Dec 09 06:22:41 volumio volumio[32575]: info: Setting Geolocation for MyVolumio to us4
Dec 09 06:22:41 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:41 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:41 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="obtained new client token: AADnl5gtmdIJuYFlvvTZXOcwzXXoZVmU+c3kVowvDo+3XUw7DENN8jwLtzBFgycPSpcewIxnlcn4YZ115v9IZCDGZWs3QxAnUDYhY+gCVodh8RwQmozuywkTCX74yuv6ce8l8Nm4XkghUp0i6Q7bDnSt8xUtiaYPjkHyxo5vFoBYg25+J0Uy6Q9ZR6Ltb8aEewbiAE29jgLdilFOWAoEO/7iAtW3pEa2TESkvr5vHyXwQdVWEsMhU27T/g=="
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=debug msg="completed challenge"
Dec 09 06:22:41 volumio volumio[32575]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 06:22:41 volumio go-librespot[651]: time="2025-12-09T06:22:41-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:42 volumio volumio[32575]: info: Updating MyVolumio device info
Dec 09 06:22:42 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:42 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:42 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:42 volumio volumio[32575]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 06:22:42 volumio volumio[32575]: info: Initializing connection to go-librespot Websocket
Dec 09 06:22:42 volumio volumio[32575]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:22:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32.
Dec 09 06:22:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:44 volumio go-librespot[672]: go-librespot daemon starting...
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=debug msg="app state loaded"
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:44 volumio go-librespot[673]: time="2025-12-09T06:22:44-06:00" level=info msg="zeroconf server listening on port 41831"
Dec 09 06:22:45 volumio go-librespot[673]: time="2025-12-09T06:22:45-06:00" level=debug msg="obtained new client token: AAAVhclJdcUKsihtnVMwU59XGbPM8L555DZ1a2UiI7eFXbZJVmxe6FiWktZr1WJkXCXs0TbO95yN1qNThtOxCvYOrRly7gTODPI2KPFxODZJo4cgsed2dwQoSxc39ljG4tZbFbflohClkqJ5OdG7zEx5Vf4MlzBsfxYhjOz6/+rFmqyRmFTZEbXaNFUpN7/AixuxYxopEoOaf4JLtoZa3e+Cjv6Jn9AkTpi4Kb+klM8BR4ibpKm0cLc="
Dec 09 06:22:45 volumio go-librespot[673]: time="2025-12-09T06:22:45-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:45 volumio go-librespot[673]: time="2025-12-09T06:22:45-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:45 volumio go-librespot[673]: time="2025-12-09T06:22:45-06:00" level=debug msg="completed challenge"
Dec 09 06:22:45 volumio go-librespot[673]: time="2025-12-09T06:22:45-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:45 volumio volumio[32575]: info: MYVOLUMIO: Adding device
Dec 09 06:22:45 volumio volumio[32575]: info: MYVOLUMIO: Evaluating Server
Dec 09 06:22:45 volumio volumio[32575]: info: Initializing connection to go-librespot Websocket
Dec 09 06:22:45 volumio volumio[32575]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:22:46 volumio volumio[32575]: info: Setting Geolocation for MyVolumio to us4
Dec 09 06:22:46 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:46 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:46 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:46 volumio volumio[32575]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 09 06:22:47 volumio volumio[32575]: info: Updating MyVolumio device info
Dec 09 06:22:47 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:47 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:47 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:47 volumio volumio[32575]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 09 06:22:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 33.
Dec 09 06:22:48 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:48 volumio go-librespot[724]: go-librespot daemon starting...
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="app state loaded"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=info msg="zeroconf server listening on port 35379"
Dec 09 06:22:48 volumio volumio[32575]: info: Initializing connection to go-librespot Websocket
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="new websocket client"
Dec 09 06:22:48 volumio volumio[32575]: info: Connection to go-librespot Websocket established
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="obtained new client token: AADuuJ30gYPQaMUx/HSdsM4tcKxoVohICTDlY6rDCQvDzpwToHbzGP1FesijTsiOpPkmBDrKYS0UQgbX5/ZtZcrltEV0/6l+YAf1k0tiEfzMOpcoVmqHOdtRxch10OooLowpjGHEvBHmlGw8StsZDhH4E5pTx1x6DvZFylUQ4fgr5PwGEgKfcim7eWYXTUlFwmV3lDSi2Zn8Rue4WtFs2xYifOmOs/fuxTfPvBLy/i495NSdqSvIejhmrg=="
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=debug msg="completed challenge"
Dec 09 06:22:48 volumio go-librespot[726]: time="2025-12-09T06:22:48-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:49 volumio volumio[32575]: info: Connection to go-librespot Websocket closed
Dec 09 06:22:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 09 06:22:51 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 06:22:51 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 09 06:22:51 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 09 06:22:51 volumio volumio-remote-updater[9752]: Test mode disabled
Dec 09 06:22:51 volumio volumio-remote-updater[9752]: Alpha mode disabled
Dec 09 06:22:51 volumio volumio-remote-updater[9752]: Alpha legacy test mode disabled
Dec 09 06:22:51 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 09 06:22:51 volumio volumio[32575]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"ANNOUNCEMENT
\n\n- Production line
\n
\nFIX
\n\n- Nodejs 20.5.1 version pinning with static package fallback
\n
\n","title":"Update v4.073","updateavailable":true}
Dec 09 06:22:51 volumio volumio[32575]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 09 06:22:51 volumio volumio[32575]: info: Getting Spotify volume
Dec 09 06:22:51 volumio volumio[32575]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 06:22:51 volumio volumio[32575]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 09 06:22:51 volumio volumio[32575]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 09 06:22:51 volumio volumio[32575]: errno: -111,
Dec 09 06:22:51 volumio volumio[32575]: code: 'ECONNREFUSED',
Dec 09 06:22:51 volumio volumio[32575]: syscall: 'connect',
Dec 09 06:22:51 volumio volumio[32575]: address: '127.0.0.1',
Dec 09 06:22:51 volumio volumio[32575]: port: 9879,
Dec 09 06:22:51 volumio volumio[32575]: response: undefined
Dec 09 06:22:51 volumio volumio[32575]: }
Dec 09 06:22:51 volumio volumio[32575]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 06:22:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34.
Dec 09 06:22:52 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:52 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 09 06:22:52 volumio go-librespot[752]: go-librespot daemon starting...
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=info msg="running go-librespot 0.4.0"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="app state loaded"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="stored credentials not found"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=info msg="zeroconf server listening on port 34757"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="obtained new client token: AABNRLWAka1LPe4fmXhc/Lts5slRFXi9U8qls+9xzQjOnztl1tP4xqvrIeRgcSEwi1+v3yBjp4+omniv1N1PfpOK3F6BXQCHPUJI/bKaN/tZ6i/04wDWuIQvZzfuxWYo9yE8SwBbd4HyN/3Jh1IU3nLtUAskWtyJLbUMk2zVH1tNmZ7tYz18N8hwkEfNIdtylWj3/7cShk138zk+5tSb7Xb/HXkSsXGppU7C4md4fWPj9YlsPLFwJhxjwg=="
Dec 09 06:22:52 volumio sudo[764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 06:21'
Dec 09 06:22:52 volumio sudo[764]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="completed keyexchange"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=debug msg="completed challenge"
Dec 09 06:22:52 volumio go-librespot[753]: time="2025-12-09T06:22:52-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 09 06:22:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 09 06:22:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
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"