Dec 29 16:11:00 music go-librespot[13431]: time="2025-12-29T16:11:00-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:11:00 music go-librespot[13431]: time="2025-12-29T16:11:00-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:11:00 music go-librespot[13431]: time="2025-12-29T16:11:00-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:11:00 music go-librespot[13431]: time="2025-12-29T16:11:00-05:00" level=info msg="zeroconf server listening on port 36077" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=debug msg="obtained new client token: AACoUEegKJPog5exYE2y7VnUMXHe10skJtaBD1UFSc7Rf/pjpxOff1/nFKAGzfLO+25wZWWDzE23920oPs8v5aJ0L+9t30xhjNq6hB37o8ENXRKCkeLgUClupkM0vz19DR4Q2NTAJ9o8Aoxxx7gRwXqAZ2cdL7JnC1loWZAiq8JtRohRtWHrEC/OtyeEvvDViWofw6VmbmPwFR7r5hWzXnoyYZsRBRrr0c+2+jBb4kl52Bj1WaNCzQ==" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=debug msg="completed challenge" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:01 music sudo[13522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:11:01 music sudo[13522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:01 music sudo[13524]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:11:01 music sudo[13524]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:01 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:11:01 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:11:01 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:01 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:01 music sudo[13522]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:01 music sudo[13524]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:01 music volumio[13237]: info: Successfully started MPD Monitor Dec 29 16:11:01 music mpd_monitor.sh[13527]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:11:01 music volumio[13237]: info: Successfully started MPD Monitor Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=debug msg="completed challenge" Dec 29 16:11:01 music go-librespot[13431]: time="2025-12-29T16:11:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:02 music volumio[13237]: info: Initializing connection to go-librespot Websocket Dec 29 16:11:02 music go-librespot[13431]: time="2025-12-29T16:11:02-05:00" level=debug msg="new websocket client" Dec 29 16:11:02 music volumio[13237]: info: Connection to go-librespot Websocket established Dec 29 16:11:02 music go-librespot[13431]: time="2025-12-29T16:11:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:11:02 music go-librespot[13431]: time="2025-12-29T16:11:02-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:02 music go-librespot[13431]: time="2025-12-29T16:11:02-05:00" level=debug msg="completed challenge" Dec 29 16:11:02 music go-librespot[13431]: time="2025-12-29T16:11:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:03 music go-librespot[13431]: time="2025-12-29T16:11:03-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 29 16:11:03 music go-librespot[13431]: time="2025-12-29T16:11:03-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:03 music go-librespot[13431]: time="2025-12-29T16:11:03-05:00" level=debug msg="completed challenge" Dec 29 16:11:03 music go-librespot[13431]: time="2025-12-29T16:11:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:03 music volumio[13237]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 29 16:11:04 music go-librespot[13431]: time="2025-12-29T16:11:04-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 29 16:11:04 music go-librespot[13431]: time="2025-12-29T16:11:04-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:04 music go-librespot[13431]: time="2025-12-29T16:11:04-05:00" level=debug msg="completed challenge" Dec 29 16:11:04 music go-librespot[13431]: time="2025-12-29T16:11:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:04 music go-librespot[13431]: time="2025-12-29T16:11:04-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 29 16:11:05 music go-librespot[13431]: time="2025-12-29T16:11:05-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:05 music go-librespot[13431]: time="2025-12-29T16:11:05-05:00" level=debug msg="completed challenge" Dec 29 16:11:05 music volumio[13237]: info: Getting Spotify volume Dec 29 16:11:05 music volumio[13237]: 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 29 16:11:05 music volumio[13237]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:05 music volumio[13237]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:05 music volumio[13237]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 29 16:11:05 music volumio[13237]: SPOTIFY: SPOTIFY VOLUME undefined Dec 29 16:11:05 music volumio[13237]: SPOTIFY: VOLUMIO VOLUME 86 Dec 29 16:11:05 music volumio[13237]: info: Aligning Spotify Volume to Volumio Volume Dec 29 16:11:05 music volumio[13237]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:05 music go-librespot[13431]: time="2025-12-29T16:11:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:05 music go-librespot[13431]: time="2025-12-29T16:11:05-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:05 music volumio[13237]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:05 music volumio[13237]: info: Setting Spotify Volume from Volumio: 86 Dec 29 16:11:05 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:05 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:11:05 music volumio[13237]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:11:05 music volumio[13237]: Error: socket hang up Dec 29 16:11:05 music volumio[13237]: at connResetException (node:internal/errors:720:14) Dec 29 16:11:05 music volumio[13237]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 29 16:11:05 music volumio[13237]: at Socket.emit (node:events:526:35) Dec 29 16:11:05 music volumio[13237]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 29 16:11:05 music volumio[13237]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 29 16:11:05 music volumio[13237]: code: 'ECONNRESET', Dec 29 16:11:05 music volumio[13237]: response: undefined Dec 29 16:11:05 music volumio[13237]: } Dec 29 16:11:05 music volumio[13237]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:11:05 music sudo[13545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 16:10' Dec 29 16:11:05 music sudo[13545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:06 music sudo[13545]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:06 music volumio-remote-updater[735]: [2025-12-29 21:11:06] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 29 16:11:06 music volumio-remote-updater[735]: [2025-12-29 21:11:06] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 29 16:11:06 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:06 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 29 16:11:06 music systemd[1]: volumio.service: Consumed 23.396s CPU time. Dec 29 16:11:06 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:11:06 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:11:06 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7573. Dec 29 16:11:06 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:11:06 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 29 16:11:06 music systemd[1]: volumio.service: Consumed 23.396s CPU time. Dec 29 16:11:06 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 29 16:11:06 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:11:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 29 16:11:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:08 music go-librespot[13573]: go-librespot daemon starting... Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=debug msg="app state loaded" Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:11:08 music volumio[13558]: info: ------------------------------------------- Dec 29 16:11:08 music volumio[13558]: info: ----- Volumio3 ---- Dec 29 16:11:08 music volumio[13558]: info: ------------------------------------------- Dec 29 16:11:08 music volumio[13558]: info: ----- System startup ---- Dec 29 16:11:08 music volumio[13558]: info: ------------------------------------------- Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=info msg="zeroconf server listening on port 37031" Dec 29 16:11:08 music go-librespot[13574]: time="2025-12-29T16:11:08-05:00" level=debug msg="obtained new client token: AADXslZ1+1/hwH/iu/mzzbGkwTPHb3REZvMHMaEiM1w29Nh+AWG91n8/J8SCb9Wp4oxs11Zxp3p9pmUiqLd+XP65emz9LjR3HZ39gDJsPrkPjm7xS5uZz46GHFhPdJ0QSjF6MQ2WubeFstd1HgovYwiKaBRe7W3fiYr51vp8phnelZuJUqTTas2R3QxKnvG18oSsvv0lbT/K6LCWhmRD9xo1yr0JFL2C/NMxwHobvWJmpj458mCVapb7" Dec 29 16:11:09 music go-librespot[13574]: time="2025-12-29T16:11:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:09 music go-librespot[13574]: time="2025-12-29T16:11:09-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:09 music go-librespot[13574]: time="2025-12-29T16:11:09-05:00" level=debug msg="completed challenge" Dec 29 16:11:09 music go-librespot[13574]: time="2025-12-29T16:11:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:09 music volumio[13558]: info: MYVOLUMIO Environment detected Dec 29 16:11:09 music volumio[13558]: info: Plugin folders cleanup Dec 29 16:11:09 music volumio[13558]: info: Scanning into folder /volumio/app/plugins/ Dec 29 16:11:09 music volumio[13558]: info: Scanning category audio_interface Dec 29 16:11:09 music volumio[13558]: info: Scanning category miscellanea Dec 29 16:11:09 music volumio[13558]: info: Scanning category music_service Dec 29 16:11:09 music volumio[13558]: info: Scanning category plugins.json Dec 29 16:11:09 music volumio[13558]: info: Scanning category system_controller Dec 29 16:11:09 music volumio[13558]: info: Scanning category user_interface Dec 29 16:11:09 music volumio[13558]: info: Scanning into folder /data/plugins/ Dec 29 16:11:09 music volumio[13558]: info: Scanning category music_service Dec 29 16:11:09 music volumio[13558]: info: Plugin folders cleanup completed Dec 29 16:11:09 music volumio[13558]: info: ------------------------------------------- Dec 29 16:11:09 music volumio[13558]: info: ----- Core plugins startup ---- Dec 29 16:11:09 music volumio[13558]: info: ------------------------------------------- Dec 29 16:11:09 music volumio[13558]: info: Loading plugins from folder /volumio/app/plugins/ Dec 29 16:11:09 music volumio[13558]: info: Adding plugin upnp to MyMusic Plugins Dec 29 16:11:09 music volumio[13558]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 29 16:11:09 music volumio[13558]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 29 16:11:09 music volumio[13558]: info: Loading plugins from folder /data/plugins/ Dec 29 16:11:09 music volumio[13558]: info: Loading plugin "system"... Dec 29 16:11:09 music volumio[13558]: info: Loading plugin "appearance"... Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "network"... Dec 29 16:11:10 music volumio[13558]: info: Refreshing Cached IP Addresses Dec 29 16:11:10 music sudo[13596]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:11:10 music sudo[13596]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:10 music sudo[13598]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:11:10 music sudo[13598]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:10 music sudo[13596]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "services"... Dec 29 16:11:10 music sudo[13598]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "alsa_controller"... Dec 29 16:11:10 music sudo[13607]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 29 16:11:10 music sudo[13607]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:10 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "wizard"... Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "networkfs"... Dec 29 16:11:10 music volumio[13558]: info: Starting Udev Watcher for removable devices Dec 29 16:11:10 music volumio[13558]: info: Ignoring mount for partition: boot Dec 29 16:11:10 music volumio[13558]: info: Ignoring mount for partition: volumio Dec 29 16:11:10 music volumio[13558]: info: Ignoring mount for partition: volumio_data Dec 29 16:11:10 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "volumio_command_line_client"... Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "upnp"... Dec 29 16:11:10 music volumio[13558]: info: [1767042670993] Starting Upmpd Daemon Dec 29 16:11:10 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:11:10 music volumio[13558]: info: Loading plugin "my_music"... Dec 29 16:11:11 music volumio[13558]: info: Loading plugin "mpd"... Dec 29 16:11:11 music volumio-remote-updater[735]: [2025-12-29 21:11:11] [connect] Successful connection Dec 29 16:11:11 music volumio[13558]: info: Loading plugin "upnp_browser"... Dec 29 16:11:11 music sudo[13607]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:12 music volumio[13558]: info: Starting UPNP Browser Dec 29 16:11:12 music volumio[13558]: info: Loading plugin "alarm-clock"... Dec 29 16:11:13 music volumio[13558]: info: Loading plugin "airplay_emulation"... Dec 29 16:11:13 music volumio[13558]: info: Starting Shairport Sync Dec 29 16:11:13 music volumio[13558]: info: Loading plugin "last_100"... Dec 29 16:11:13 music volumio[13558]: info: Loading plugin "webradio"... Dec 29 16:11:13 music volumio[13558]: info: Loading plugin "i2s_dacs"... Dec 29 16:11:13 music volumio[13558]: info: I2S DAC not set, start Auto-detection Dec 29 16:11:13 music volumio[13558]: info: Loading plugin "volumiodiscovery"... Dec 29 16:11:13 music volumio[13558]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:13 music volumio[13558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:13 music volumio[13558]: *** WARNING *** For more information see Dec 29 16:11:13 music volumio[13558]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:13 music volumio[13558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:13 music volumio[13558]: *** WARNING *** For more information see Dec 29 16:11:13 music node[13558]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:13 music node[13558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:13 music node[13558]: *** WARNING *** For more information see Dec 29 16:11:13 music node[13558]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:13 music node[13558]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:13 music node[13558]: *** WARNING *** For more information see Dec 29 16:11:13 music volumio[13558]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 29 16:11:13 music volumio[13558]: info: Discovery: Started advertising with name: music Dec 29 16:11:13 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:11:13 music volumio[13558]: info: Loading plugin "spop"... Dec 29 16:11:14 music volumio[13558]: info: Loading plugin "outputs"... Dec 29 16:11:14 music volumio[13558]: info: Loading plugin "albumart"... Dec 29 16:11:14 music volumio[13558]: info: Plugin example_plugin is not enabled Dec 29 16:11:14 music volumio[13558]: info: Loading plugin "inputs"... Dec 29 16:11:14 music volumio[13558]: info: Loading plugin "updater_comm"... Dec 29 16:11:14 music volumio[13558]: info: Plugin mpdemulation is not enabled Dec 29 16:11:14 music volumio[13558]: info: Loading plugin "rest_api"... Dec 29 16:11:14 music volumio[13558]: info: Loading plugin "websocket"... Dec 29 16:11:14 music volumio[13558]: info: Starting Socket.io Server version 1.7.4 Dec 29 16:11:14 music volumio[13558]: info: Loading i18n strings for locale en Dec 29 16:11:14 music volumio[13558]: Updating browse sources language Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:14 music go-librespot[13574]: time="2025-12-29T16:11:14-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::initPlayerControls Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:11:14 music volumio[13558]: Express server listening on port 3000 Dec 29 16:11:14 music volumio[13558]: [Metrics] WebUI: 6s 702.09ms Dec 29 16:11:14 music volumio[13558]: info: CoreStateMachine::resetVolumioState Dec 29 16:11:14 music volumio[13558]: info: CoreStateMachine::getcurrentVolume Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:11:14 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:14 music volumio[13558]: info: Volumio Network Manager: Network status updated: 1 Dec 29 16:11:15 music volumio-remote-updater[735]: [2025-12-29 21:11:15] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767042671 101 Dec 29 16:11:15 music volumio[13631]: Forking 3 albumart workers Dec 29 16:11:15 music volumio[13558]: 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 29 16:11:15 music volumio[13558]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:11:15 music volumio[13558]: info: CoreStateMachine::pushState Dec 29 16:11:15 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:15 music volumio[13558]: info: CoreStateMachine::updateTrackBlock Dec 29 16:11:15 music volumio[13558]: info: CorePlayQueue::getTrackBlock Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:11:15 music volumio[13558]: info: Reloading queue from file Dec 29 16:11:15 music volumio[13558]: info: CoreStateMachine::setRepeat null single undefined Dec 29 16:11:15 music volumio[13558]: info: CoreStateMachine::pushState Dec 29 16:11:15 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:15 music volumio[13558]: info: CoreStateMachine::setRandom null Dec 29 16:11:15 music volumio[13558]: info: CoreStateMachine::pushState Dec 29 16:11:15 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:15 music volumio[13558]: info: Setting Device type: Raspberry PI Dec 29 16:11:15 music volumio[13558]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:11:15 music volumio[13558]: info: CoreStateMachine::pushState Dec 29 16:11:15 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:15 music volumio[13558]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:11:15 music volumio[13558]: info: Discovery: Found device music Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:15 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:15 music volumio[13558]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:11:15 music volumio[13558]: info: Discovery: Found device music Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:15 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:15 music volumio[13558]: info: Completed loading Core Plugins Dec 29 16:11:15 music volumio[13558]: info: Preparing to generate the ALSA configuration file Dec 29 16:11:15 music volumio[13558]: info: Asound.conf file unchanged, so no further update is needed Dec 29 16:11:15 music volumio[13558]: info: Output device has changed, restarting MPD Dec 29 16:11:15 music volumio[13558]: info: Output device has changed, restarting Shairport Sync Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:15 music sudo[13686]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:11:15 music sudo[13686]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:15 music sudo[13686]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:15 music sudo[13687]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:11:15 music sudo[13687]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:15 music volumio[13558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:11:15 music volumio[13558]: info: ___________ START PLUGINS ___________ Dec 29 16:11:15 music volumio[13558]: info: ControllerMpd::onStart: Initializing MPD Dec 29 16:11:15 music volumio[13558]: info: Creating MPD Configuration file Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:11:15 music volumio[13558]: info: [1767042675503] CoreMusicLibrary::Adding element Media Servers Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:15 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 29 16:11:15 music sudo[13697]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:11:15 music sudo[13697]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:15 music sudo[13695]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:11:15 music sudo[13695]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:15 music volumio[13558]: info: UPNP Browser: Client initialized successfully Dec 29 16:11:15 music sudo[13695]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:15 music systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:11:15 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:11:15 music systemd[1]: mpd.service: Consumed 4.094s CPU time. Dec 29 16:11:15 music systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:11:15 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:11:15 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:11:15 music volumio[13558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:15 music volumio[13558]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:11:15 music volumio[13558]: info: [1767042675700] CoreMusicLibrary::Adding element Last_100 Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:11:15 music volumio[13558]: info: [1767042675705] CoreMusicLibrary::Adding element Webradio Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:11:15 music volumio[13558]: info: Initializing BBC Radios Dec 29 16:11:15 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:11:15 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:11:15 music systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:11:15 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:11:15 music systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:11:15 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:11:15 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:11:15 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:11:15 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:15 music volumio[13558]: info: Creating Spotify config file Dec 29 16:11:15 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:16 music go-librespot[13574]: time="2025-12-29T16:11:16-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:16 music go-librespot[13574]: time="2025-12-29T16:11:16-05:00" level=debug msg="completed challenge" Dec 29 16:11:16 music sudo[13719]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 16:11:16 music sudo[13719]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 16:11:16 music sudo[13719]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:16 music go-librespot[13574]: time="2025-12-29T16:11:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:16 music volumio[13558]: info: Volumio Calling Home Dec 29 16:11:16 music go-librespot[13574]: time="2025-12-29T16:11:16-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:11:16 music go-librespot[13574]: time="2025-12-29T16:11:16-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:16 music go-librespot[13574]: time="2025-12-29T16:11:16-05:00" level=debug msg="completed challenge" Dec 29 16:11:16 music go-librespot[13574]: time="2025-12-29T16:11:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:17 music volumio[13647]: Starting albumart workers Dec 29 16:11:17 music volumio[13648]: Starting albumart workers Dec 29 16:11:17 music volumio[13558]: info: MPD Permissions set Dec 29 16:11:17 music volumio[13558]: info: MPD Permissions set Dec 29 16:11:17 music volumio[13646]: Starting albumart workers Dec 29 16:11:17 music volumio[13558]: info: Volumio called home Dec 29 16:11:17 music volumio[13558]: info: Spotify config file written Dec 29 16:11:17 music sudo[13731]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 16:11:17 music sudo[13731]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:17 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 16:11:17 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 16:11:17 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:17 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:17 music go-librespot[13733]: go-librespot daemon starting... Dec 29 16:11:17 music sudo[13731]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:17 music go-librespot[13734]: time="2025-12-29T16:11:17-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:11:17 music go-librespot[13734]: time="2025-12-29T16:11:17-05:00" level=debug msg="app state loaded" Dec 29 16:11:17 music go-librespot[13734]: time="2025-12-29T16:11:17-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:11:17 music volumio[13558]: 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 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:17 music volumio[13558]: info: No need to fix Spotify hosts Dec 29 16:11:17 music go-librespot[13734]: time="2025-12-29T16:11:17-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 29 16:11:17 music go-librespot[13734]: time="2025-12-29T16:11:17-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 29 16:11:17 music go-librespot[13734]: time="2025-12-29T16:11:17-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 29 16:11:18 music go-librespot[13734]: time="2025-12-29T16:11:18-05:00" level=info msg="zeroconf server listening on port 41299" Dec 29 16:11:18 music go-librespot[13734]: time="2025-12-29T16:11:18-05:00" level=debug msg="obtained new client token: AADpL+gl5B51H2KDLQge+bSSjfgELZDOJwdlosYrGL5QFYKEYw1NPFxhMHRGExhEdLPa9YEUp5wrnBhE6r5B+kqVDp9tToq6QPJ2JPgGcUpv9o1JUfMjfscu1vJV4NZtzuD+V6iUDxTcDRYbtaIk9utRnhzVTLIoxkSmwb3oGFcnaRtWGvEpKfW8ubdCSDZg7H5Tq+RpDlRJ9HX9bROxpMHLg5bq/K2ewxkOzkbW2mMDtSEf51x5uQ==" Dec 29 16:11:18 music volumio[13558]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 29 16:11:18 music go-librespot[13734]: time="2025-12-29T16:11:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:18 music volumio[13558]: info: Starting Shairport Sync Dec 29 16:11:18 music volumio[13558]: info: Starting Shairport Sync Dec 29 16:11:18 music volumio[13558]: info: Starting Shairport Sync Dec 29 16:11:18 music go-librespot[13734]: time="2025-12-29T16:11:18-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:18 music go-librespot[13734]: time="2025-12-29T16:11:18-05:00" level=debug msg="completed challenge" Dec 29 16:11:18 music sudo[13760]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:11:18 music sudo[13760]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:18 music sudo[13762]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:11:18 music sudo[13762]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:18 music sudo[13764]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:11:18 music go-librespot[13734]: time="2025-12-29T16:11:18-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:18 music sudo[13764]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:18 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:11:18 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:11:18 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:18 music systemd[1]: shairport-sync.service: Consumed 1.729s CPU time. Dec 29 16:11:18 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:18 music volumio[13558]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:18 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:18 music sudo[13762]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:18 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:11:18 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:11:18 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:18 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:18 music sudo[13760]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:18 music volumio[13558]: info: Shairport-Sync Started Dec 29 16:11:18 music volumio[13558]: Error adding Membership: Error: addMembership EINVAL Dec 29 16:11:18 music sudo[13764]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:18 music volumio[13558]: info: Shairport-Sync Started Dec 29 16:11:18 music volumio[13558]: info: Shairport-Sync Started Dec 29 16:11:18 music go-librespot[13734]: time="2025-12-29T16:11:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:11:19 music go-librespot[13734]: time="2025-12-29T16:11:19-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:19 music go-librespot[13734]: time="2025-12-29T16:11:19-05:00" level=debug msg="completed challenge" Dec 29 16:11:19 music go-librespot[13734]: time="2025-12-29T16:11:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:19 music go-librespot[13734]: time="2025-12-29T16:11:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:11:19 music go-librespot[13734]: time="2025-12-29T16:11:19-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:19 music go-librespot[13734]: time="2025-12-29T16:11:19-05:00" level=debug msg="completed challenge" Dec 29 16:11:19 music go-librespot[13734]: time="2025-12-29T16:11:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:20 music mpd[13726]: 2025-12-29T16:11:20 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 29 16:11:20 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 29 16:11:20 music sudo[13697]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:20 music sudo[13687]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:20 music volumio[13558]: info: Completed starting Core Plugins Dec 29 16:11:20 music volumio[13558]: info: ------------------------------------------- Dec 29 16:11:20 music volumio[13558]: info: ----- MyVolumio plugins startup ---- Dec 29 16:11:20 music volumio[13558]: info: ------------------------------------------- Dec 29 16:11:20 music volumio[13558]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 29 16:11:20 music volumio[13558]: error: MPD error: The expression evaluated to a falsy value: Dec 29 16:11:20 music volumio[13558]: assert.ok(self.idling) Dec 29 16:11:20 music volumio[13558]: error: The expression evaluated to a falsy value: Dec 29 16:11:20 music volumio[13558]: assert.ok(self.idling) Dec 29 16:11:20 music volumio[13558]: info: MPD running with PID13726 Dec 29 16:11:20 music volumio[13558]: ,establishing connection Dec 29 16:11:20 music volumio[13558]: error: updateQueue error: null Dec 29 16:11:20 music volumio[13558]: error: updateQueue error: null Dec 29 16:11:20 music go-librespot[13734]: time="2025-12-29T16:11:20-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 29 16:11:20 music go-librespot[13734]: time="2025-12-29T16:11:20-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:20 music go-librespot[13734]: time="2025-12-29T16:11:20-05:00" level=debug msg="completed challenge" Dec 29 16:11:20 music go-librespot[13734]: time="2025-12-29T16:11:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:21 music sudo[13817]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:11:21 music sudo[13817]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:21 music sudo[13817]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:21 music sudo[13819]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:11:21 music sudo[13819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:21 music sudo[13819]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:21 music sudo[13822]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 29 16:11:21 music sudo[13822]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:21 music sudo[13822]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:21 music volumio[13558]: info: Upmpdcli Daemon Started Dec 29 16:11:21 music volumio[13558]: info: go-librespot daemon successfully initialized Dec 29 16:11:21 music go-librespot[13734]: time="2025-12-29T16:11:21-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 29 16:11:21 music go-librespot[13734]: time="2025-12-29T16:11:21-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:21 music go-librespot[13734]: time="2025-12-29T16:11:21-05:00" level=debug msg="completed challenge" Dec 29 16:11:21 music go-librespot[13734]: time="2025-12-29T16:11:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:22 music go-librespot[13734]: time="2025-12-29T16:11:22-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 29 16:11:22 music go-librespot[13734]: time="2025-12-29T16:11:22-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:22 music go-librespot[13734]: time="2025-12-29T16:11:22-05:00" level=debug msg="completed challenge" Dec 29 16:11:22 music go-librespot[13734]: time="2025-12-29T16:11:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:22 music go-librespot[13734]: time="2025-12-29T16:11:22-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:22 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:22 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:11:23 music sudo[13829]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:11:23 music sudo[13829]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:23 music sudo[13831]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:11:23 music sudo[13831]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:23 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:11:23 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:11:23 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:23 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:23 music mpd_monitor.sh[13834]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:11:23 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:11:23 music sudo[13829]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:23 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:11:23 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:23 music volumio[13558]: info: Successfully started MPD Monitor Dec 29 16:11:23 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:23 music sudo[13831]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:23 music mpd_monitor.sh[13836]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:11:23 music volumio[13558]: info: Successfully started MPD Monitor Dec 29 16:11:24 music volumio[13558]: info: Initializing connection to go-librespot Websocket Dec 29 16:11:24 music volumio[13558]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 16:11:25 music volumio[13558]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 29 16:11:25 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 29 16:11:25 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:25 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:25 music go-librespot[13840]: go-librespot daemon starting... Dec 29 16:11:25 music go-librespot[13841]: time="2025-12-29T16:11:25-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:11:25 music go-librespot[13841]: time="2025-12-29T16:11:25-05:00" level=debug msg="app state loaded" Dec 29 16:11:25 music go-librespot[13841]: time="2025-12-29T16:11:25-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:11:25 music go-librespot[13841]: time="2025-12-29T16:11:25-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:11:25 music go-librespot[13841]: time="2025-12-29T16:11:25-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:11:25 music go-librespot[13841]: time="2025-12-29T16:11:25-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:11:25 music go-librespot[13841]: time="2025-12-29T16:11:25-05:00" level=info msg="zeroconf server listening on port 34987" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=debug msg="obtained new client token: AAC9OWbnvixQ08U4Kx3D3NfnFFqn789tFKXvqHStHeUC6PXRjwWZts7qTfa/xLs5FscNrOJenXU4DZBAfJ4J4P7gBM31bIu9mj/QwkPXQWNS39idtz60zopuA4zPxqRen+IYJcHLNNS6apjqcYXuzZ42/k1urP9EtiJjcX4WUPyuH3rGLO1hZLEBt3VnbD7gUUCKslI05qYw5Xpyt9OgFjsEHQyWcxzCLrvRYHkOIjNUZ0QBglJ9lA==" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=debug msg="completed challenge" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=debug msg="completed challenge" Dec 29 16:11:26 music go-librespot[13841]: time="2025-12-29T16:11:26-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:27 music volumio[13558]: info: Initializing connection to go-librespot Websocket Dec 29 16:11:27 music go-librespot[13841]: time="2025-12-29T16:11:27-05:00" level=debug msg="new websocket client" Dec 29 16:11:27 music volumio[13558]: info: Connection to go-librespot Websocket established Dec 29 16:11:27 music go-librespot[13841]: time="2025-12-29T16:11:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:11:27 music go-librespot[13841]: time="2025-12-29T16:11:27-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:27 music go-librespot[13841]: time="2025-12-29T16:11:27-05:00" level=debug msg="completed challenge" Dec 29 16:11:27 music go-librespot[13841]: time="2025-12-29T16:11:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:28 music go-librespot[13841]: time="2025-12-29T16:11:28-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 29 16:11:28 music volumio[13558]: info: Adding plugin bluetooth to MyMusic Plugins Dec 29 16:11:28 music volumio[13558]: info: Adding plugin multiroom to MyMusic Plugins Dec 29 16:11:28 music volumio[13558]: info: Adding plugin metavolumio to MyMusic Plugins Dec 29 16:11:28 music volumio[13558]: info: Adding plugin cd_controller to MyMusic Plugins Dec 29 16:11:28 music volumio[13558]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 29 16:11:28 music volumio[13558]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 29 16:11:28 music volumio[13558]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 29 16:11:28 music volumio[13558]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 29 16:11:29 music volumio[13558]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 29 16:11:29 music volumio[13558]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 29 16:11:29 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:29 music volumio[13558]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:29 music volumio[13558]: info: Starting MyVolumio Remote Streaming Endpoints Dec 29 16:11:29 music volumio[13558]: info: MyVolumio login type: Token Dec 29 16:11:29 music volumio[13558]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 29 16:11:29 music volumio[13558]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 29 16:11:30 music volumio[13558]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 29 16:11:30 music volumio[13558]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 29 16:11:30 music volumio[13558]: info: Streaming services startup Dec 29 16:11:30 music volumio[13558]: info: Starting Streaming Daemon Dec 29 16:11:30 music sudo[13852]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 29 16:11:30 music sudo[13852]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:30 music volumio[13558]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 29 16:11:30 music sudo[13852]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:30 music volumio[13558]: info: Getting Spotify volume Dec 29 16:11:30 music volumio[13558]: error: Cannot start Volumio Streaming Daemon Dec 29 16:11:30 music volumio[13558]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 29 16:11:30 music volumio[13558]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 29 16:11:30 music volumio[13558]: 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 29 16:11:30 music go-librespot[13841]: time="2025-12-29T16:11:30-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:30 music go-librespot[13841]: time="2025-12-29T16:11:30-05:00" level=debug msg="completed challenge" Dec 29 16:11:30 music go-librespot[13841]: time="2025-12-29T16:11:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:30 music volumio[13558]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:30 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:30 music volumio[13558]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 29 16:11:30 music volumio[13558]: SPOTIFY: SPOTIFY VOLUME undefined Dec 29 16:11:30 music volumio[13558]: SPOTIFY: VOLUMIO VOLUME 86 Dec 29 16:11:30 music volumio[13558]: info: Aligning Spotify Volume to Volumio Volume Dec 29 16:11:30 music volumio[13558]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:30 music volumio[13558]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:30 music volumio[13558]: info: Setting Spotify Volume from Volumio: 86 Dec 29 16:11:31 music volumio[13558]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 29 16:11:31 music go-librespot[13841]: time="2025-12-29T16:11:31-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 29 16:11:31 music volumio[13558]: info: MyVolumio token set successfully Dec 29 16:11:31 music volumio[13558]: info: MYVOLUMIO: Adding device Dec 29 16:11:31 music volumio[13558]: info: MYVOLUMIO: Evaluating Server Dec 29 16:11:31 music go-librespot[13841]: time="2025-12-29T16:11:31-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:31 music go-librespot[13841]: time="2025-12-29T16:11:31-05:00" level=debug msg="completed challenge" Dec 29 16:11:31 music go-librespot[13841]: time="2025-12-29T16:11:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:31 music volumio[13558]: info: MyVolumio status changed Dec 29 16:11:31 music volumio[13558]: info: Streaming services startup Dec 29 16:11:31 music volumio[13558]: info: Starting Streaming Daemon Dec 29 16:11:31 music volumio[13558]: info: Removing browser output: myVolumio user plan is not superstar Dec 29 16:11:31 music volumio[13558]: info: Removing audio output: Dec 29 16:11:31 music volumio[13558]: info: Stoppping Tunnel 1 Dec 29 16:11:31 music sudo[13893]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 29 16:11:31 music sudo[13893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:31 music sudo[13895]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Dec 29 16:11:31 music sudo[13895]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:31 music 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 29 16:11:31 music 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 29 16:11:31 music sudo[13893]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:31 music volumio[13558]: error: Cannot start Volumio Streaming Daemon Dec 29 16:11:31 music volumio[13558]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 29 16:11:31 music volumio[13558]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 29 16:11:31 music 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 29 16:11:31 music 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 29 16:11:31 music 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 29 16:11:31 music 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 29 16:11:31 music 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 29 16:11:31 music 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 29 16:11:31 music sudo[13895]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:31 music volumio[13558]: info: Remote SSH Stopped Dec 29 16:11:32 music go-librespot[13841]: time="2025-12-29T16:11:32-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 29 16:11:32 music go-librespot[13841]: time="2025-12-29T16:11:32-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:32 music go-librespot[13841]: time="2025-12-29T16:11:32-05:00" level=debug msg="completed challenge" Dec 29 16:11:32 music volumio[13558]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Dec 29 16:11:32 music volumio[13558]: info: Sending Spotify command with payload to local API: /player/volume Dec 29 16:11:32 music go-librespot[13841]: time="2025-12-29T16:11:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:32 music go-librespot[13841]: time="2025-12-29T16:11:32-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:32 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:32 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:11:32 music volumio[13558]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Dec 29 16:11:32 music volumio[13558]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:11:32 music volumio[13558]: Error: socket hang up Dec 29 16:11:32 music volumio[13558]: at connResetException (node:internal/errors:720:14) Dec 29 16:11:32 music volumio[13558]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 29 16:11:32 music volumio[13558]: at Socket.emit (node:events:526:35) Dec 29 16:11:32 music volumio[13558]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 29 16:11:32 music volumio[13558]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 29 16:11:32 music volumio[13558]: code: 'ECONNRESET', Dec 29 16:11:32 music volumio[13558]: response: undefined Dec 29 16:11:32 music volumio[13558]: } Dec 29 16:11:32 music volumio[13558]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:11:33 music sudo[13912]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 16:10' Dec 29 16:11:33 music sudo[13912]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:33 music sudo[13912]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:33 music volumio-remote-updater[735]: [2025-12-29 21:11:33] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 29 16:11:33 music volumio-remote-updater[735]: [2025-12-29 21:11:33] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 29 16:11:33 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:33 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 29 16:11:33 music systemd[1]: volumio.service: Consumed 27.549s CPU time. Dec 29 16:11:33 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:11:33 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:11:33 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7574. Dec 29 16:11:33 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:11:33 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 29 16:11:33 music systemd[1]: volumio.service: Consumed 27.549s CPU time. Dec 29 16:11:33 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 29 16:11:33 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:11:35 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 29 16:11:35 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:35 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:35 music go-librespot[13940]: go-librespot daemon starting... Dec 29 16:11:35 music go-librespot[13941]: time="2025-12-29T16:11:35-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:11:35 music go-librespot[13941]: time="2025-12-29T16:11:35-05:00" level=debug msg="app state loaded" Dec 29 16:11:35 music go-librespot[13941]: time="2025-12-29T16:11:35-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:11:35 music volumio[13924]: info: ------------------------------------------- Dec 29 16:11:35 music volumio[13924]: info: ----- Volumio3 ---- Dec 29 16:11:35 music volumio[13924]: info: ------------------------------------------- Dec 29 16:11:35 music volumio[13924]: info: ----- System startup ---- Dec 29 16:11:35 music volumio[13924]: info: ------------------------------------------- Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=info msg="zeroconf server listening on port 45941" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="obtained new client token: AABlYixUaByAuybceaMQ5gwL/WWunA+nDHJfqrkXO/cUrrJ8Y6qvWg51VdHLwMVV+YyiHTibFGZXwg3S/o5XUUpL12SSmYVg6Y4K1tigSfScbKTrO+DYivyImZ4OfXOgECqd1k8gAMWN1UZimKyRr4f1e0TYYJvITJBGUJs63MdV0avO6nw3R8BXNI/RJJy3+36iAvaT0Ef1Hu5nZbq8bKId8amr85sdHyTcleTsODSVtktP+X6PHA==" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="completed challenge" Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:36 music volumio[13924]: info: MYVOLUMIO Environment detected Dec 29 16:11:36 music volumio[13924]: info: Plugin folders cleanup Dec 29 16:11:36 music volumio[13924]: info: Scanning into folder /volumio/app/plugins/ Dec 29 16:11:36 music volumio[13924]: info: Scanning category audio_interface Dec 29 16:11:36 music volumio[13924]: info: Scanning category miscellanea Dec 29 16:11:36 music volumio[13924]: info: Scanning category music_service Dec 29 16:11:36 music volumio[13924]: info: Scanning category plugins.json Dec 29 16:11:36 music volumio[13924]: info: Scanning category system_controller Dec 29 16:11:36 music volumio[13924]: info: Scanning category user_interface Dec 29 16:11:36 music volumio[13924]: info: Scanning into folder /data/plugins/ Dec 29 16:11:36 music volumio[13924]: info: Scanning category music_service Dec 29 16:11:36 music volumio[13924]: info: Plugin folders cleanup completed Dec 29 16:11:36 music volumio[13924]: info: ------------------------------------------- Dec 29 16:11:36 music volumio[13924]: info: ----- Core plugins startup ---- Dec 29 16:11:36 music volumio[13924]: info: ------------------------------------------- Dec 29 16:11:36 music volumio[13924]: info: Loading plugins from folder /volumio/app/plugins/ Dec 29 16:11:36 music volumio[13924]: info: Adding plugin upnp to MyMusic Plugins Dec 29 16:11:36 music volumio[13924]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 29 16:11:36 music volumio[13924]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 29 16:11:36 music volumio[13924]: info: Loading plugins from folder /data/plugins/ Dec 29 16:11:36 music volumio[13924]: info: Loading plugin "system"... Dec 29 16:11:36 music volumio[13924]: info: Loading plugin "appearance"... Dec 29 16:11:36 music go-librespot[13941]: time="2025-12-29T16:11:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:11:37 music go-librespot[13941]: time="2025-12-29T16:11:37-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:37 music go-librespot[13941]: time="2025-12-29T16:11:37-05:00" level=debug msg="completed challenge" Dec 29 16:11:37 music go-librespot[13941]: time="2025-12-29T16:11:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:37 music go-librespot[13941]: time="2025-12-29T16:11:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:11:37 music go-librespot[13941]: time="2025-12-29T16:11:37-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:37 music go-librespot[13941]: time="2025-12-29T16:11:37-05:00" level=debug msg="completed challenge" Dec 29 16:11:37 music go-librespot[13941]: time="2025-12-29T16:11:37-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "network"... Dec 29 16:11:38 music volumio[13924]: info: Refreshing Cached IP Addresses Dec 29 16:11:38 music sudo[13963]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:11:38 music sudo[13963]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:38 music sudo[13965]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "services"... Dec 29 16:11:38 music sudo[13965]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:38 music sudo[13963]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "alsa_controller"... Dec 29 16:11:38 music sudo[13965]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:38 music sudo[13972]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 29 16:11:38 music sudo[13972]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:38 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "wizard"... Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "networkfs"... Dec 29 16:11:38 music volumio[13924]: info: Starting Udev Watcher for removable devices Dec 29 16:11:38 music volumio[13924]: info: Ignoring mount for partition: boot Dec 29 16:11:38 music volumio[13924]: info: Ignoring mount for partition: volumio Dec 29 16:11:38 music volumio[13924]: info: Ignoring mount for partition: volumio_data Dec 29 16:11:38 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "volumio_command_line_client"... Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "upnp"... Dec 29 16:11:38 music volumio[13924]: info: [1767042698256] Starting Upmpd Daemon Dec 29 16:11:38 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "my_music"... Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "mpd"... Dec 29 16:11:38 music go-librespot[13941]: time="2025-12-29T16:11:38-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 29 16:11:38 music go-librespot[13941]: time="2025-12-29T16:11:38-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:38 music go-librespot[13941]: time="2025-12-29T16:11:38-05:00" level=debug msg="completed challenge" Dec 29 16:11:38 music volumio-remote-updater[735]: [2025-12-29 21:11:38] [connect] Successful connection Dec 29 16:11:38 music go-librespot[13941]: time="2025-12-29T16:11:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:38 music volumio[13924]: info: Loading plugin "upnp_browser"... Dec 29 16:11:38 music sudo[13972]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:39 music go-librespot[13941]: time="2025-12-29T16:11:39-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 29 16:11:39 music go-librespot[13941]: time="2025-12-29T16:11:39-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:39 music go-librespot[13941]: time="2025-12-29T16:11:39-05:00" level=debug msg="completed challenge" Dec 29 16:11:39 music go-librespot[13941]: time="2025-12-29T16:11:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:40 music volumio[13924]: info: Starting UPNP Browser Dec 29 16:11:40 music volumio[13924]: info: Loading plugin "alarm-clock"... Dec 29 16:11:40 music go-librespot[13941]: time="2025-12-29T16:11:40-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 29 16:11:40 music volumio[13924]: info: Loading plugin "airplay_emulation"... Dec 29 16:11:40 music volumio[13924]: info: Starting Shairport Sync Dec 29 16:11:40 music volumio[13924]: info: Loading plugin "last_100"... Dec 29 16:11:40 music volumio[13924]: info: Loading plugin "webradio"... Dec 29 16:11:40 music go-librespot[13941]: time="2025-12-29T16:11:40-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:40 music go-librespot[13941]: time="2025-12-29T16:11:40-05:00" level=debug msg="completed challenge" Dec 29 16:11:40 music volumio[13924]: info: Loading plugin "i2s_dacs"... Dec 29 16:11:40 music volumio[13924]: info: I2S DAC not set, start Auto-detection Dec 29 16:11:40 music volumio[13924]: info: Loading plugin "volumiodiscovery"... Dec 29 16:11:40 music volumio[13924]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:40 music volumio[13924]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:40 music volumio[13924]: *** WARNING *** For more information see Dec 29 16:11:40 music volumio[13924]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:40 music volumio[13924]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:40 music volumio[13924]: *** WARNING *** For more information see Dec 29 16:11:40 music node[13924]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:40 music node[13924]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:40 music node[13924]: *** WARNING *** For more information see Dec 29 16:11:40 music node[13924]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:11:40 music node[13924]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:11:40 music node[13924]: *** WARNING *** For more information see Dec 29 16:11:40 music volumio[13924]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 29 16:11:40 music volumio[13924]: info: Discovery: Started advertising with name: music Dec 29 16:11:40 music go-librespot[13941]: time="2025-12-29T16:11:40-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:40 music go-librespot[13941]: time="2025-12-29T16:11:40-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:40 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:40 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:11:40 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:11:40 music volumio[13924]: info: Loading plugin "spop"... Dec 29 16:11:41 music volumio[13924]: info: Loading plugin "outputs"... Dec 29 16:11:41 music volumio[13924]: info: Loading plugin "albumart"... Dec 29 16:11:41 music volumio[13924]: info: Plugin example_plugin is not enabled Dec 29 16:11:41 music volumio[13924]: info: Loading plugin "inputs"... Dec 29 16:11:41 music volumio[13924]: info: Loading plugin "updater_comm"... Dec 29 16:11:41 music volumio[13924]: info: Plugin mpdemulation is not enabled Dec 29 16:11:41 music volumio[13924]: info: Loading plugin "rest_api"... Dec 29 16:11:41 music volumio[13924]: info: Loading plugin "websocket"... Dec 29 16:11:41 music volumio[13924]: info: Starting Socket.io Server version 1.7.4 Dec 29 16:11:41 music volumio[13924]: info: Loading i18n strings for locale en Dec 29 16:11:41 music volumio[13924]: Updating browse sources language Dec 29 16:11:41 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::initPlayerControls Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:11:42 music volumio[13924]: Express server listening on port 3000 Dec 29 16:11:42 music volumio[13924]: [Metrics] WebUI: 6s 691.93ms Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::resetVolumioState Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::getcurrentVolume Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: Volumio Network Manager: Network status updated: 1 Dec 29 16:11:42 music volumio-remote-updater[735]: [2025-12-29 21:11:42] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767042698 101 Dec 29 16:11:42 music volumio[13998]: Forking 3 albumart workers Dec 29 16:11:42 music volumio[13924]: 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 29 16:11:42 music volumio[13924]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::pushState Dec 29 16:11:42 music volumio[13924]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::updateTrackBlock Dec 29 16:11:42 music volumio[13924]: info: CorePlayQueue::getTrackBlock Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:11:42 music volumio[13924]: info: Reloading queue from file Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::setRepeat null single undefined Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::pushState Dec 29 16:11:42 music volumio[13924]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::setRandom null Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::pushState Dec 29 16:11:42 music volumio[13924]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:42 music volumio[13924]: info: Setting Device type: Raspberry PI Dec 29 16:11:42 music volumio[13924]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:11:42 music volumio[13924]: info: CoreStateMachine::pushState Dec 29 16:11:42 music volumio[13924]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioPushState Dec 29 16:11:42 music volumio[13924]: info: Completed loading Core Plugins Dec 29 16:11:42 music volumio[13924]: info: Preparing to generate the ALSA configuration file Dec 29 16:11:42 music volumio[13924]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:11:42 music volumio[13924]: info: Discovery: Found device music Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:42 music volumio[13924]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:42 music volumio[13924]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:11:42 music volumio[13924]: info: Discovery: Found device music Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:42 music volumio[13924]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:42 music volumio[13924]: info: Asound.conf file unchanged, so no further update is needed Dec 29 16:11:42 music volumio[13924]: info: Output device has changed, restarting MPD Dec 29 16:11:42 music volumio[13924]: info: Output device has changed, restarting Shairport Sync Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:42 music sudo[14052]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:11:42 music sudo[14052]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:42 music volumio[13924]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:11:42 music sudo[14054]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:11:42 music sudo[14054]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:42 music volumio[13924]: info: ___________ START PLUGINS ___________ Dec 29 16:11:42 music sudo[14052]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:42 music volumio[13924]: info: ControllerMpd::onStart: Initializing MPD Dec 29 16:11:42 music volumio[13924]: info: Creating MPD Configuration file Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:11:42 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 29 16:11:42 music volumio[13924]: info: [1767042702780] CoreMusicLibrary::Adding element Media Servers Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:42 music sudo[14064]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:11:42 music sudo[14064]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:42 music sudo[14063]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:11:42 music sudo[14063]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:42 music sudo[14063]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:42 music volumio[13924]: info: UPNP Browser: Client initialized successfully Dec 29 16:11:42 music systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:11:42 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:11:42 music systemd[1]: mpd.service: Consumed 4.130s CPU time. Dec 29 16:11:42 music systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:11:42 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:11:42 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:42 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:11:42 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:11:42 music volumio[13924]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:42 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:43 music volumio[13924]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:11:43 music volumio[13924]: info: [1767042703033] CoreMusicLibrary::Adding element Last_100 Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:11:43 music volumio[13924]: info: [1767042703038] CoreMusicLibrary::Adding element Webradio Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:11:43 music volumio[13924]: info: Initializing BBC Radios Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:43 music volumio[13924]: info: Creating Spotify config file Dec 29 16:11:43 music sudo[14072]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 16:11:43 music sudo[14072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 16:11:43 music sudo[14072]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:43 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:43 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 29 16:11:43 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:43 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:43 music go-librespot[14094]: go-librespot daemon starting... Dec 29 16:11:43 music volumio[13924]: info: Volumio Calling Home Dec 29 16:11:43 music go-librespot[14095]: time="2025-12-29T16:11:43-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:11:44 music volumio[14013]: Starting albumart workers Dec 29 16:11:44 music go-librespot[14095]: time="2025-12-29T16:11:44-05:00" level=info msg="zeroconf server listening on port 39197" Dec 29 16:11:44 music volumio[14014]: Starting albumart workers Dec 29 16:11:44 music volumio[13924]: info: MPD Permissions set Dec 29 16:11:44 music volumio[13924]: info: MPD Permissions set Dec 29 16:11:44 music volumio[13924]: info: Spotify config file written Dec 29 16:11:44 music volumio[13924]: 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 29 16:11:44 music volumio[13924]: info: Volumio called home Dec 29 16:11:44 music sudo[14108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 16:11:44 music sudo[14108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 16:11:44 music systemd[1]: go-librespot-daemon.service: Killing process 14100 (go-librespot) with signal SIGKILL. Dec 29 16:11:44 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 16:11:44 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:44 music go-librespot[14115]: go-librespot daemon starting... Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:44 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:11:44 music sudo[14108]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:44 music volumio[13924]: info: No need to fix Spotify hosts Dec 29 16:11:44 music go-librespot[14121]: time="2025-12-29T16:11:44-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:11:44 music go-librespot[14121]: time="2025-12-29T16:11:44-05:00" level=debug msg="app state loaded" Dec 29 16:11:44 music go-librespot[14121]: time="2025-12-29T16:11:44-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:11:45 music volumio[14015]: Starting albumart workers Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:11:45 music volumio[13924]: info: Starting Shairport Sync Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=info msg="zeroconf server listening on port 38427" Dec 29 16:11:45 music volumio[13924]: info: Starting Shairport Sync Dec 29 16:11:45 music volumio[13924]: info: Starting Shairport Sync Dec 29 16:11:45 music sudo[14132]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:11:45 music sudo[14132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:45 music volumio[13924]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 29 16:11:45 music sudo[14136]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:11:45 music sudo[14136]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:45 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:11:45 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:11:45 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:45 music systemd[1]: shairport-sync.service: Consumed 1.884s CPU time. Dec 29 16:11:45 music sudo[14134]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:11:45 music sudo[14134]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=debug msg="obtained new client token: AACrC+lPqNQHk5945ieDgh6AJBa6K+3DPM7Xn7j2/TsHd9mS0/GUSRqstiuD8MdIe1KOo0OjBoPLC9BpLaq3Fbkyl5TkDTLdTfzVZslZ3rB7zyOEO7aaIiks8igiBJ0QiCmKD1CN7PeClPRaSCGGqoMpbMN/66wNqbUJ4yH1Lc6cplfEe8IU0MPCmzLYE9Ai/ehrx7lkMFtTh0/BSov1BseE6oycnmXcbdAKdWa2KHWIL0ajFDw3BLFj" Dec 29 16:11:45 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:45 music sudo[14132]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:45 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=debug msg="completed challenge" Dec 29 16:11:45 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:11:45 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:45 music volumio[13924]: info: CoreCommandRouter::volumioGetState Dec 29 16:11:45 music volumio[13924]: info: CorePlayQueue::getTrack 0 Dec 29 16:11:45 music go-librespot[14121]: time="2025-12-29T16:11:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:45 music volumio[13924]: info: Shairport-Sync Started Dec 29 16:11:45 music volumio[13924]: Error adding Membership: Error: addMembership EINVAL Dec 29 16:11:45 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:11:45 music sudo[14134]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:45 music sudo[14136]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:45 music volumio[13924]: info: Shairport-Sync Started Dec 29 16:11:45 music volumio[13924]: info: Shairport-Sync Started Dec 29 16:11:46 music go-librespot[14121]: time="2025-12-29T16:11:46-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:11:46 music go-librespot[14121]: time="2025-12-29T16:11:46-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:46 music go-librespot[14121]: time="2025-12-29T16:11:46-05:00" level=debug msg="completed challenge" Dec 29 16:11:46 music go-librespot[14121]: time="2025-12-29T16:11:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:47 music go-librespot[14121]: time="2025-12-29T16:11:47-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:11:47 music go-librespot[14121]: time="2025-12-29T16:11:47-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:47 music go-librespot[14121]: time="2025-12-29T16:11:47-05:00" level=debug msg="completed challenge" Dec 29 16:11:47 music go-librespot[14121]: time="2025-12-29T16:11:47-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:47 music mpd[14091]: 2025-12-29T16:11:47 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 29 16:11:47 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 29 16:11:47 music sudo[14064]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:47 music sudo[14054]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:47 music volumio[13924]: info: Completed starting Core Plugins Dec 29 16:11:47 music volumio[13924]: info: ------------------------------------------- Dec 29 16:11:47 music volumio[13924]: info: ----- MyVolumio plugins startup ---- Dec 29 16:11:47 music volumio[13924]: info: ------------------------------------------- Dec 29 16:11:47 music volumio[13924]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 29 16:11:47 music volumio[13924]: error: MPD error: The expression evaluated to a falsy value: Dec 29 16:11:47 music volumio[13924]: assert.ok(self.idling) Dec 29 16:11:47 music volumio[13924]: error: The expression evaluated to a falsy value: Dec 29 16:11:47 music volumio[13924]: assert.ok(self.idling) Dec 29 16:11:47 music volumio[13924]: info: MPD running with PID14091 Dec 29 16:11:47 music volumio[13924]: ,establishing connection Dec 29 16:11:47 music volumio[13924]: error: updateQueue error: null Dec 29 16:11:47 music volumio[13924]: error: updateQueue error: null Dec 29 16:11:47 music go-librespot[14121]: time="2025-12-29T16:11:47-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 29 16:11:48 music go-librespot[14121]: time="2025-12-29T16:11:48-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:48 music go-librespot[14121]: time="2025-12-29T16:11:48-05:00" level=debug msg="completed challenge" Dec 29 16:11:48 music sudo[14208]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:11:48 music sudo[14208]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:48 music sudo[14208]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:48 music sudo[14210]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:11:48 music sudo[14210]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:48 music sudo[14210]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:48 music go-librespot[14121]: time="2025-12-29T16:11:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:48 music sudo[14212]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 29 16:11:48 music sudo[14212]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:48 music volumio[13924]: info: go-librespot daemon successfully initialized Dec 29 16:11:48 music sudo[14212]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:48 music volumio[13924]: info: Upmpdcli Daemon Started Dec 29 16:11:48 music go-librespot[14121]: time="2025-12-29T16:11:48-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=debug msg="completed challenge" Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:80, retrying with a different AP" error="dial tcp 34.158.1.133:80: connect: connection refused" Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=debug msg="completed challenge" Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:49 music go-librespot[14121]: time="2025-12-29T16:11:49-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:49 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:49 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:11:50 music sudo[14217]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:11:50 music sudo[14217]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:50 music sudo[14219]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:11:50 music sudo[14219]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:50 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:11:50 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:11:50 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:50 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:50 music sudo[14217]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:50 music mpd_monitor.sh[14222]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:11:50 music volumio[13924]: info: Successfully started MPD Monitor Dec 29 16:11:50 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:11:50 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:11:50 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:50 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:11:50 music sudo[14219]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:50 music mpd_monitor.sh[14225]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:11:50 music volumio[13924]: info: Successfully started MPD Monitor Dec 29 16:11:51 music volumio[13924]: info: Initializing connection to go-librespot Websocket Dec 29 16:11:51 music volumio[13924]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 16:11:52 music volumio[13924]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 29 16:11:53 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 29 16:11:53 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:53 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:11:53 music go-librespot[14229]: go-librespot daemon starting... Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="app state loaded" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=info msg="zeroconf server listening on port 38889" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="obtained new client token: AADEOQCkYsoBW+TTpu/FbXtX/yCrgfo+UsJ1L1fXCeWE370iSi7CR+PSfTJNNzHp2zRoWtlpuDBaDHwJNve8GAmgFhprtBbcaDnSBXjycLIN2hRdCg4CfYe/ZJVaDFNA59LNcUMWNLvMqrgvPtcH19rsMJwx0MNkE6HNlXflPtrd8u8yQfG1LVjKr0hbz7W+xEOyQtT5QqKliMhe3tpYHfoNKV9k+NBGcE0SZO5Mmy5kYiQpfbwwVP9T" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=debug msg="completed challenge" Dec 29 16:11:53 music go-librespot[14230]: time="2025-12-29T16:11:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:54 music volumio[13924]: info: Initializing connection to go-librespot Websocket Dec 29 16:11:54 music go-librespot[14230]: time="2025-12-29T16:11:54-05:00" level=debug msg="new websocket client" Dec 29 16:11:54 music volumio[13924]: info: Connection to go-librespot Websocket established Dec 29 16:11:54 music go-librespot[14230]: time="2025-12-29T16:11:54-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:11:54 music go-librespot[14230]: time="2025-12-29T16:11:54-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:54 music go-librespot[14230]: time="2025-12-29T16:11:54-05:00" level=debug msg="completed challenge" Dec 29 16:11:54 music go-librespot[14230]: time="2025-12-29T16:11:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:55 music go-librespot[14230]: time="2025-12-29T16:11:55-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:11:55 music go-librespot[14230]: time="2025-12-29T16:11:55-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:55 music go-librespot[14230]: time="2025-12-29T16:11:55-05:00" level=debug msg="completed challenge" Dec 29 16:11:55 music go-librespot[14230]: time="2025-12-29T16:11:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:55 music go-librespot[14230]: time="2025-12-29T16:11:55-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 29 16:11:55 music volumio[13924]: info: Adding plugin bluetooth to MyMusic Plugins Dec 29 16:11:55 music volumio[13924]: info: Adding plugin multiroom to MyMusic Plugins Dec 29 16:11:55 music volumio[13924]: info: Adding plugin metavolumio to MyMusic Plugins Dec 29 16:11:55 music volumio[13924]: info: Adding plugin cd_controller to MyMusic Plugins Dec 29 16:11:55 music volumio[13924]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 29 16:11:55 music volumio[13924]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 29 16:11:55 music volumio[13924]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 29 16:11:55 music volumio[13924]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 29 16:11:56 music go-librespot[14230]: time="2025-12-29T16:11:56-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:56 music go-librespot[14230]: time="2025-12-29T16:11:56-05:00" level=debug msg="completed challenge" Dec 29 16:11:56 music go-librespot[14230]: time="2025-12-29T16:11:56-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:56 music go-librespot[14230]: time="2025-12-29T16:11:56-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 29 16:11:57 music volumio[13924]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 29 16:11:57 music volumio[13924]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 29 16:11:57 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:57 music volumio[13924]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:11:57 music volumio[13924]: info: Starting MyVolumio Remote Streaming Endpoints Dec 29 16:11:57 music volumio[13924]: info: MyVolumio login type: Token Dec 29 16:11:57 music go-librespot[14230]: time="2025-12-29T16:11:57-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:57 music go-librespot[14230]: time="2025-12-29T16:11:57-05:00" level=debug msg="completed challenge" Dec 29 16:11:57 music volumio[13924]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 29 16:11:57 music volumio[13924]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 29 16:11:57 music go-librespot[14230]: time="2025-12-29T16:11:57-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:57 music go-librespot[14230]: time="2025-12-29T16:11:57-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 29 16:11:57 music go-librespot[14230]: time="2025-12-29T16:11:57-05:00" level=debug msg="completed keyexchange" Dec 29 16:11:57 music go-librespot[14230]: time="2025-12-29T16:11:57-05:00" level=debug msg="completed challenge" Dec 29 16:11:57 music volumio[13924]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 29 16:11:57 music volumio[13924]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 29 16:11:57 music volumio[13924]: info: Streaming services startup Dec 29 16:11:57 music volumio[13924]: info: Starting Streaming Daemon Dec 29 16:11:58 music sudo[14240]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 29 16:11:58 music sudo[14240]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:58 music volumio[13924]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 29 16:11:58 music go-librespot[14230]: time="2025-12-29T16:11:58-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:58 music go-librespot[14230]: time="2025-12-29T16:11:58-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:11:58 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:11:58 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:11:58 music sudo[14240]: pam_unix(sudo:session): session closed for user root Dec 29 16:11:58 music volumio[13924]: info: Getting Spotify volume Dec 29 16:11:58 music volumio[13924]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:11:58 music volumio[13924]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 16:11:58 music volumio[13924]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 29 16:11:58 music volumio[13924]: errno: -111, Dec 29 16:11:58 music volumio[13924]: code: 'ECONNREFUSED', Dec 29 16:11:58 music volumio[13924]: syscall: 'connect', Dec 29 16:11:58 music volumio[13924]: address: '127.0.0.1', Dec 29 16:11:58 music volumio[13924]: port: 9879, Dec 29 16:11:58 music volumio[13924]: response: undefined Dec 29 16:11:58 music volumio[13924]: } Dec 29 16:11:58 music volumio[13924]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:11:58 music sudo[14275]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 16:10' Dec 29 16:11:58 music sudo[14275]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:11:59 music sudo[14275]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:01 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 29 16:12:01 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:01 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:01 music go-librespot[14283]: go-librespot daemon starting... Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="app state loaded" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:12:01 music volumio-remote-updater[735]: [2025-12-29 21:12:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 29 16:12:01 music volumio-remote-updater[735]: [2025-12-29 21:12:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 29 16:12:01 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:01 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 29 16:12:01 music systemd[1]: volumio.service: Consumed 26.642s CPU time. Dec 29 16:12:01 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:12:01 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=info msg="zeroconf server listening on port 36659" Dec 29 16:12:01 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7575. Dec 29 16:12:01 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:12:01 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 29 16:12:01 music systemd[1]: volumio.service: Consumed 26.642s CPU time. Dec 29 16:12:01 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 29 16:12:01 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="obtained new client token: AAByZRwb0JbkPbsF3h3Xa4dRtK2n5A/1zgYc2V9js3Cx+s/i3smcCG9B++wnuN+kWYCTbA2eszIjkdCM7r8VN+zwRxBjV/OPmP2ZBF5ktXypN0saSmrNOzNgYfGO2nKfB79whHAIwb1dkY1oqUMEkU+F/i5fVtXgrYrAKGn6BhkOiB4fijVMwRkCK/KORCL1YW8apDl0htfC6Zmd0Cuz218762IsXhQQn1LtqncYvSo3rNPy5lHzY7Ys" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=debug msg="completed challenge" Dec 29 16:12:01 music go-librespot[14284]: time="2025-12-29T16:12:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:02 music go-librespot[14284]: time="2025-12-29T16:12:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:12:03 music go-librespot[14284]: time="2025-12-29T16:12:03-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:03 music go-librespot[14284]: time="2025-12-29T16:12:03-05:00" level=debug msg="completed challenge" Dec 29 16:12:03 music go-librespot[14284]: time="2025-12-29T16:12:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:03 music volumio[14300]: info: ------------------------------------------- Dec 29 16:12:03 music volumio[14300]: info: ----- Volumio3 ---- Dec 29 16:12:03 music volumio[14300]: info: ------------------------------------------- Dec 29 16:12:03 music volumio[14300]: info: ----- System startup ---- Dec 29 16:12:03 music volumio[14300]: info: ------------------------------------------- Dec 29 16:12:03 music go-librespot[14284]: time="2025-12-29T16:12:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:12:03 music go-librespot[14284]: time="2025-12-29T16:12:03-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:03 music go-librespot[14284]: time="2025-12-29T16:12:03-05:00" level=debug msg="completed challenge" Dec 29 16:12:03 music go-librespot[14284]: time="2025-12-29T16:12:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:04 music volumio[14300]: info: MYVOLUMIO Environment detected Dec 29 16:12:04 music volumio[14300]: info: Plugin folders cleanup Dec 29 16:12:04 music volumio[14300]: info: Scanning into folder /volumio/app/plugins/ Dec 29 16:12:04 music volumio[14300]: info: Scanning category audio_interface Dec 29 16:12:04 music volumio[14300]: info: Scanning category miscellanea Dec 29 16:12:04 music volumio[14300]: info: Scanning category music_service Dec 29 16:12:04 music volumio[14300]: info: Scanning category plugins.json Dec 29 16:12:04 music volumio[14300]: info: Scanning category system_controller Dec 29 16:12:04 music volumio[14300]: info: Scanning category user_interface Dec 29 16:12:04 music volumio[14300]: info: Scanning into folder /data/plugins/ Dec 29 16:12:04 music volumio[14300]: info: Scanning category music_service Dec 29 16:12:04 music volumio[14300]: info: Plugin folders cleanup completed Dec 29 16:12:04 music volumio[14300]: info: ------------------------------------------- Dec 29 16:12:04 music volumio[14300]: info: ----- Core plugins startup ---- Dec 29 16:12:04 music volumio[14300]: info: ------------------------------------------- Dec 29 16:12:04 music volumio[14300]: info: Loading plugins from folder /volumio/app/plugins/ Dec 29 16:12:04 music volumio[14300]: info: Adding plugin upnp to MyMusic Plugins Dec 29 16:12:04 music volumio[14300]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 29 16:12:04 music volumio[14300]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 29 16:12:04 music volumio[14300]: info: Loading plugins from folder /data/plugins/ Dec 29 16:12:04 music volumio[14300]: info: Loading plugin "system"... Dec 29 16:12:04 music volumio[14300]: info: Loading plugin "appearance"... Dec 29 16:12:04 music go-librespot[14284]: time="2025-12-29T16:12:04-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 29 16:12:05 music go-librespot[14284]: time="2025-12-29T16:12:05-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:05 music go-librespot[14284]: time="2025-12-29T16:12:05-05:00" level=debug msg="completed challenge" Dec 29 16:12:05 music go-librespot[14284]: time="2025-12-29T16:12:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "network"... Dec 29 16:12:05 music volumio[14300]: info: Refreshing Cached IP Addresses Dec 29 16:12:05 music sudo[14328]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:12:05 music sudo[14328]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:05 music sudo[14330]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:12:05 music sudo[14328]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:05 music sudo[14330]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "services"... Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "alsa_controller"... Dec 29 16:12:05 music sudo[14330]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:05 music sudo[14338]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 29 16:12:05 music sudo[14338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:05 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "wizard"... Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "networkfs"... Dec 29 16:12:05 music volumio[14300]: info: Starting Udev Watcher for removable devices Dec 29 16:12:05 music volumio[14300]: info: Ignoring mount for partition: boot Dec 29 16:12:05 music volumio[14300]: info: Ignoring mount for partition: volumio Dec 29 16:12:05 music volumio[14300]: info: Ignoring mount for partition: volumio_data Dec 29 16:12:05 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "volumio_command_line_client"... Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "upnp"... Dec 29 16:12:05 music volumio[14300]: info: [1767042725812] Starting Upmpd Daemon Dec 29 16:12:05 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "my_music"... Dec 29 16:12:05 music volumio[14300]: info: Loading plugin "mpd"... Dec 29 16:12:05 music go-librespot[14284]: time="2025-12-29T16:12:05-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 29 16:12:06 music go-librespot[14284]: time="2025-12-29T16:12:06-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:06 music go-librespot[14284]: time="2025-12-29T16:12:06-05:00" level=debug msg="completed challenge" Dec 29 16:12:06 music volumio[14300]: info: Loading plugin "upnp_browser"... Dec 29 16:12:06 music go-librespot[14284]: time="2025-12-29T16:12:06-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:06 music sudo[14338]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:06 music volumio-remote-updater[735]: [2025-12-29 21:12:06] [connect] Successful connection Dec 29 16:12:06 music go-librespot[14284]: time="2025-12-29T16:12:06-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 29 16:12:06 music go-librespot[14284]: time="2025-12-29T16:12:06-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:06 music go-librespot[14284]: time="2025-12-29T16:12:06-05:00" level=debug msg="completed challenge" Dec 29 16:12:07 music go-librespot[14284]: time="2025-12-29T16:12:07-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:07 music go-librespot[14284]: time="2025-12-29T16:12:07-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:07 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:07 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:12:07 music volumio[14300]: info: Starting UPNP Browser Dec 29 16:12:07 music volumio[14300]: info: Loading plugin "alarm-clock"... Dec 29 16:12:07 music volumio[14300]: info: Loading plugin "airplay_emulation"... Dec 29 16:12:07 music volumio[14300]: info: Starting Shairport Sync Dec 29 16:12:07 music volumio[14300]: info: Loading plugin "last_100"... Dec 29 16:12:07 music volumio[14300]: info: Loading plugin "webradio"... Dec 29 16:12:08 music volumio[14300]: info: Loading plugin "i2s_dacs"... Dec 29 16:12:08 music volumio[14300]: info: I2S DAC not set, start Auto-detection Dec 29 16:12:08 music volumio[14300]: info: Loading plugin "volumiodiscovery"... Dec 29 16:12:08 music volumio[14300]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:08 music volumio[14300]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:08 music volumio[14300]: *** WARNING *** For more information see Dec 29 16:12:08 music volumio[14300]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:08 music volumio[14300]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:08 music volumio[14300]: *** WARNING *** For more information see Dec 29 16:12:08 music node[14300]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:08 music node[14300]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:08 music node[14300]: *** WARNING *** For more information see Dec 29 16:12:08 music node[14300]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:08 music node[14300]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:08 music node[14300]: *** WARNING *** For more information see Dec 29 16:12:08 music volumio[14300]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 29 16:12:08 music volumio[14300]: info: Discovery: Started advertising with name: music Dec 29 16:12:08 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:12:08 music volumio[14300]: info: Loading plugin "spop"... Dec 29 16:12:09 music volumio[14300]: info: Loading plugin "outputs"... Dec 29 16:12:09 music volumio[14300]: info: Loading plugin "albumart"... Dec 29 16:12:09 music volumio[14300]: info: Plugin example_plugin is not enabled Dec 29 16:12:09 music volumio[14300]: info: Loading plugin "inputs"... Dec 29 16:12:09 music volumio[14300]: info: Loading plugin "updater_comm"... Dec 29 16:12:09 music volumio[14300]: info: Plugin mpdemulation is not enabled Dec 29 16:12:09 music volumio[14300]: info: Loading plugin "rest_api"... Dec 29 16:12:09 music volumio[14300]: info: Loading plugin "websocket"... Dec 29 16:12:09 music volumio[14300]: info: Starting Socket.io Server version 1.7.4 Dec 29 16:12:09 music volumio[14300]: info: Loading i18n strings for locale en Dec 29 16:12:09 music volumio[14300]: Updating browse sources language Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::initPlayerControls Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:12:09 music volumio[14300]: Express server listening on port 3000 Dec 29 16:12:09 music volumio[14300]: [Metrics] WebUI: 6s 526.38ms Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::resetVolumioState Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::getcurrentVolume Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:09 music volumio[14300]: info: Volumio Network Manager: Network status updated: 1 Dec 29 16:12:09 music volumio-remote-updater[735]: [2025-12-29 21:12:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767042726 101 Dec 29 16:12:09 music volumio[14300]: 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 29 16:12:09 music volumio[14300]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::pushState Dec 29 16:12:09 music volumio[14300]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::updateTrackBlock Dec 29 16:12:09 music volumio[14300]: info: CorePlayQueue::getTrackBlock Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:12:09 music volumio[14364]: Forking 3 albumart workers Dec 29 16:12:09 music volumio[14300]: info: Reloading queue from file Dec 29 16:12:09 music volumio[14300]: info: Setting Device type: Raspberry PI Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::setRepeat null single undefined Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::pushState Dec 29 16:12:09 music volumio[14300]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::setRandom null Dec 29 16:12:09 music volumio[14300]: info: CoreStateMachine::pushState Dec 29 16:12:09 music volumio[14300]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:09 music volumio[14300]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:10 music volumio[14300]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:12:10 music volumio[14300]: info: CoreStateMachine::pushState Dec 29 16:12:10 music volumio[14300]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:10 music volumio[14300]: info: Completed loading Core Plugins Dec 29 16:12:10 music volumio[14300]: info: Preparing to generate the ALSA configuration file Dec 29 16:12:10 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 29 16:12:10 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:10 music volumio[14300]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:12:10 music volumio[14300]: info: Discovery: Found device music Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:10 music volumio[14300]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:10 music volumio[14300]: info: Asound.conf file unchanged, so no further update is needed Dec 29 16:12:10 music volumio[14300]: info: Output device has changed, restarting MPD Dec 29 16:12:10 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:10 music go-librespot[14419]: go-librespot daemon starting... Dec 29 16:12:10 music volumio[14300]: info: Output device has changed, restarting Shairport Sync Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:10 music sudo[14422]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="app state loaded" Dec 29 16:12:10 music sudo[14422]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:10 music sudo[14422]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:10 music sudo[14428]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:12:10 music sudo[14428]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:12:10 music volumio[14300]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:12:10 music volumio[14300]: info: ___________ START PLUGINS ___________ Dec 29 16:12:10 music volumio[14300]: info: ControllerMpd::onStart: Initializing MPD Dec 29 16:12:10 music volumio[14300]: info: Creating MPD Configuration file Dec 29 16:12:10 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:12:10 music volumio[14300]: info: [1767042730317] CoreMusicLibrary::Adding element Media Servers Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:10 music volumio[14300]: info: UPNP Browser: Client initialized successfully Dec 29 16:12:10 music systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:12:10 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:12:10 music systemd[1]: mpd.service: Consumed 4.233s CPU time. Dec 29 16:12:10 music systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:12:10 music sudo[14439]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:12:10 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:12:10 music sudo[14439]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:10 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:10 music sudo[14439]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:10 music volumio[14300]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:10 music sudo[14441]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:12:10 music sudo[14441]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:10 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:12:10 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:12:10 music systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:12:10 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:12:10 music systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:12:10 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:12:10 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:12:10 music volumio[14300]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:12:10 music volumio[14300]: info: [1767042730563] CoreMusicLibrary::Adding element Last_100 Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:12:10 music volumio[14300]: info: [1767042730577] CoreMusicLibrary::Adding element Webradio Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:12:10 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:12:10 music volumio[14300]: info: Initializing BBC Radios Dec 29 16:12:10 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=info msg="zeroconf server listening on port 35107" Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:10 music volumio[14300]: info: Creating Spotify config file Dec 29 16:12:10 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="obtained new client token: AABhb8tJ/ws8o0AY147QlqXj9LwPXJr6MDYlhY9yIC83mTRoqn+KpB2ASqD04L0abdDCYcWljnEedy09shZArPXhPrmhfLWCAwSGx4Jj6JjiSNFg2aBbyKC9gYuiYnK6VrBzBSMKKJv40NZIeaiMsHT26+n8T56lM9Isl81j6YO/JTRfliAqTmjIlGofl2i1UfnUionXaTKDFWmfzk3d24Xo/9JBU33WGXLmrb63IBY3wuIAKxkA3Hwm" Dec 29 16:12:10 music sudo[14457]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 16:12:10 music sudo[14457]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:10 music sudo[14457]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:10 music go-librespot[14421]: time="2025-12-29T16:12:10-05:00" level=debug msg="completed challenge" Dec 29 16:12:11 music go-librespot[14421]: time="2025-12-29T16:12:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:11 music volumio[14300]: info: Volumio Calling Home Dec 29 16:12:11 music go-librespot[14421]: time="2025-12-29T16:12:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:12:11 music volumio[14300]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:12:11 music volumio[14300]: info: Discovery: Found device music Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:11 music volumio[14300]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:11 music volumio[14300]: info: MPD Permissions set Dec 29 16:12:11 music volumio[14300]: info: MPD Permissions set Dec 29 16:12:11 music go-librespot[14421]: time="2025-12-29T16:12:11-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:11 music go-librespot[14421]: time="2025-12-29T16:12:11-05:00" level=debug msg="completed challenge" Dec 29 16:12:11 music volumio[14300]: info: Volumio called home Dec 29 16:12:11 music volumio[14300]: info: Spotify config file written Dec 29 16:12:11 music go-librespot[14421]: time="2025-12-29T16:12:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:11 music sudo[14478]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 16:12:11 music sudo[14478]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:11 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 16:12:11 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 16:12:11 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:11 music volumio[14300]: 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 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:11 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:12 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:12 music volumio[14384]: Starting albumart workers Dec 29 16:12:12 music go-librespot[14480]: go-librespot daemon starting... Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music sudo[14478]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14388]: Starting albumart workers Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="app state loaded" Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:12 music volumio[14300]: info: No need to fix Spotify hosts Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=info msg="zeroconf server listening on port 36067" Dec 29 16:12:12 music volumio[14300]: info: Starting Shairport Sync Dec 29 16:12:12 music volumio[14300]: info: Starting Shairport Sync Dec 29 16:12:12 music volumio[14300]: info: Starting Shairport Sync Dec 29 16:12:12 music sudo[14501]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:12:12 music sudo[14501]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:12 music volumio[14382]: Starting albumart workers Dec 29 16:12:12 music sudo[14503]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:12:12 music sudo[14503]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="obtained new client token: AAD4YFkTWDIuQ60Bx5VXsaUTPMuRixngWDGTnqP90ZxwggvUZBJa9mN4tL66R8BWnNQ/Cz6fiAOsjKloXM8VdNZ+QF1/WvAnSx5kAqRDCF10myLtQ6hdKMTPDQo+ltrmGVXkjtgvasJ5ceiRICwYdrZqGG1nluEbJfh56EuyZgs/lTOWlYDhXNq8IP5vRMP10vQPdcoLq/0Ib9746ZzpYDaLdWpDQ5NIHGXq/X9//kD1f+wBYjG2eF0B" Dec 29 16:12:12 music volumio[14300]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 29 16:12:12 music sudo[14506]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:12:12 music sudo[14506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:12 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:12:12 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:12:12 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:12:12 music systemd[1]: shairport-sync.service: Consumed 1.817s CPU time. Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:12 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=debug msg="completed challenge" Dec 29 16:12:12 music sudo[14501]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:12 music go-librespot[14486]: time="2025-12-29T16:12:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:12 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:12:12 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:12:12 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:12:12 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:12:13 music sudo[14506]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:13 music sudo[14503]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:13 music volumio[14300]: info: Shairport-Sync Started Dec 29 16:12:13 music volumio[14300]: Error adding Membership: Error: addMembership EINVAL Dec 29 16:12:13 music volumio[14300]: info: Shairport-Sync Started Dec 29 16:12:13 music volumio[14300]: info: Shairport-Sync Started Dec 29 16:12:13 music volumio[14300]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:13 music volumio[14300]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:13 music go-librespot[14486]: time="2025-12-29T16:12:13-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:12:13 music go-librespot[14486]: time="2025-12-29T16:12:13-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:13 music go-librespot[14486]: time="2025-12-29T16:12:13-05:00" level=debug msg="completed challenge" Dec 29 16:12:13 music go-librespot[14486]: time="2025-12-29T16:12:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:14 music go-librespot[14486]: time="2025-12-29T16:12:14-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:12:14 music go-librespot[14486]: time="2025-12-29T16:12:14-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:14 music go-librespot[14486]: time="2025-12-29T16:12:14-05:00" level=debug msg="completed challenge" Dec 29 16:12:14 music go-librespot[14486]: time="2025-12-29T16:12:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:15 music go-librespot[14486]: time="2025-12-29T16:12:15-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Dec 29 16:12:15 music mpd[14473]: 2025-12-29T16:12:15 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 29 16:12:15 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 29 16:12:15 music sudo[14441]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:15 music sudo[14428]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:15 music volumio[14300]: info: Completed starting Core Plugins Dec 29 16:12:15 music volumio[14300]: info: ------------------------------------------- Dec 29 16:12:15 music volumio[14300]: info: ----- MyVolumio plugins startup ---- Dec 29 16:12:15 music volumio[14300]: info: ------------------------------------------- Dec 29 16:12:15 music volumio[14300]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 29 16:12:15 music volumio[14300]: error: MPD error: The expression evaluated to a falsy value: Dec 29 16:12:15 music volumio[14300]: assert.ok(self.idling) Dec 29 16:12:15 music volumio[14300]: error: The expression evaluated to a falsy value: Dec 29 16:12:15 music volumio[14300]: assert.ok(self.idling) Dec 29 16:12:15 music volumio[14300]: info: MPD running with PID14473 Dec 29 16:12:15 music volumio[14300]: ,establishing connection Dec 29 16:12:15 music volumio[14300]: error: updateQueue error: null Dec 29 16:12:15 music volumio[14300]: error: updateQueue error: null Dec 29 16:12:15 music go-librespot[14486]: time="2025-12-29T16:12:15-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:15 music go-librespot[14486]: time="2025-12-29T16:12:15-05:00" level=debug msg="completed challenge" Dec 29 16:12:15 music volumio[14300]: info: go-librespot daemon successfully initialized Dec 29 16:12:15 music go-librespot[14486]: time="2025-12-29T16:12:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:15 music sudo[14564]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:12:15 music sudo[14564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:15 music sudo[14566]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:12:15 music sudo[14566]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:15 music sudo[14564]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:15 music sudo[14566]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:15 music sudo[14568]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 29 16:12:15 music sudo[14568]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:15 music sudo[14568]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:15 music volumio[14300]: info: Upmpdcli Daemon Started Dec 29 16:12:16 music go-librespot[14486]: time="2025-12-29T16:12:16-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 29 16:12:16 music go-librespot[14486]: time="2025-12-29T16:12:16-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:16 music go-librespot[14486]: time="2025-12-29T16:12:16-05:00" level=debug msg="completed challenge" Dec 29 16:12:16 music go-librespot[14486]: time="2025-12-29T16:12:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:17 music go-librespot[14486]: time="2025-12-29T16:12:17-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 29 16:12:17 music go-librespot[14486]: time="2025-12-29T16:12:17-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:17 music go-librespot[14486]: time="2025-12-29T16:12:17-05:00" level=debug msg="completed challenge" Dec 29 16:12:17 music go-librespot[14486]: time="2025-12-29T16:12:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:17 music go-librespot[14486]: time="2025-12-29T16:12:17-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:17 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:17 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:12:18 music sudo[14573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:12:18 music sudo[14573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:18 music sudo[14575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:12:18 music sudo[14575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:18 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:12:18 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:12:18 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:12:18 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:12:18 music sudo[14573]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:18 music volumio[14300]: info: Successfully started MPD Monitor Dec 29 16:12:18 music mpd_monitor.sh[14578]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:12:18 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:12:18 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:12:18 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:12:18 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:12:18 music sudo[14575]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:18 music mpd_monitor.sh[14580]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:12:18 music volumio[14300]: info: Successfully started MPD Monitor Dec 29 16:12:18 music volumio[14300]: info: Initializing connection to go-librespot Websocket Dec 29 16:12:18 music volumio[14300]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 16:12:20 music volumio[14300]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 29 16:12:20 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 29 16:12:20 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:20 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:20 music go-librespot[14584]: go-librespot daemon starting... Dec 29 16:12:20 music go-librespot[14585]: time="2025-12-29T16:12:20-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:20 music go-librespot[14585]: time="2025-12-29T16:12:20-05:00" level=debug msg="app state loaded" Dec 29 16:12:20 music go-librespot[14585]: time="2025-12-29T16:12:20-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:12:20 music go-librespot[14585]: time="2025-12-29T16:12:20-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:12:20 music go-librespot[14585]: time="2025-12-29T16:12:20-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:12:20 music go-librespot[14585]: time="2025-12-29T16:12:20-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:12:20 music go-librespot[14585]: time="2025-12-29T16:12:20-05:00" level=info msg="zeroconf server listening on port 36029" Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="obtained new client token: AAB1tO4YriwxDz8vEXZccFBVW+Q6cGP4JfWqpimJ+scahqDOzrJNdRaSBD5sK7BHPqpWa8I1Ea4fU/9yZrAUzGZuk+9d3ugWuEyu6kLNadFCPrPybUzNJQIVCnApHg5Gsh6jPXVvbDcelzk1TIocLsxWV7tD0pwn6c/jwd1r2dUsSfYJ05JJ3TkIVz2AB5oaqCt+ulZhj2wO7ikqPCSCPlsKLzCHfAgPdbaxgEOKmK/w/UalDnphOw==" Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="completed challenge" Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:21 music volumio[14300]: info: Initializing connection to go-librespot Websocket Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="new websocket client" Dec 29 16:12:21 music volumio[14300]: info: Connection to go-librespot Websocket established Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:21 music go-librespot[14585]: time="2025-12-29T16:12:21-05:00" level=debug msg="completed challenge" Dec 29 16:12:22 music go-librespot[14585]: time="2025-12-29T16:12:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:22 music go-librespot[14585]: time="2025-12-29T16:12:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:12:22 music go-librespot[14585]: time="2025-12-29T16:12:22-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:22 music go-librespot[14585]: time="2025-12-29T16:12:22-05:00" level=debug msg="completed challenge" Dec 29 16:12:22 music go-librespot[14585]: time="2025-12-29T16:12:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 29 16:12:23 music volumio[14300]: info: Adding plugin bluetooth to MyMusic Plugins Dec 29 16:12:23 music volumio[14300]: info: Adding plugin multiroom to MyMusic Plugins Dec 29 16:12:23 music volumio[14300]: info: Adding plugin metavolumio to MyMusic Plugins Dec 29 16:12:23 music volumio[14300]: info: Adding plugin cd_controller to MyMusic Plugins Dec 29 16:12:23 music volumio[14300]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 29 16:12:23 music volumio[14300]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 29 16:12:23 music volumio[14300]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 29 16:12:23 music volumio[14300]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 29 16:12:23 music go-librespot[14585]: time="2025-12-29T16:12:23-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 29 16:12:23 music go-librespot[14585]: time="2025-12-29T16:12:23-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:23 music go-librespot[14585]: time="2025-12-29T16:12:23-05:00" level=debug msg="completed challenge" Dec 29 16:12:23 music go-librespot[14585]: time="2025-12-29T16:12:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:24 music go-librespot[14585]: time="2025-12-29T16:12:24-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Dec 29 16:12:24 music volumio[14300]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 29 16:12:24 music volumio[14300]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 29 16:12:24 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:24 music go-librespot[14585]: time="2025-12-29T16:12:24-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:24 music go-librespot[14585]: time="2025-12-29T16:12:24-05:00" level=debug msg="completed challenge" Dec 29 16:12:24 music volumio[14300]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:24 music volumio[14300]: info: Starting MyVolumio Remote Streaming Endpoints Dec 29 16:12:24 music volumio[14300]: info: MyVolumio login type: Token Dec 29 16:12:24 music volumio[14300]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 29 16:12:24 music volumio[14300]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 29 16:12:24 music go-librespot[14585]: time="2025-12-29T16:12:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:25 music go-librespot[14585]: time="2025-12-29T16:12:25-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 29 16:12:25 music go-librespot[14585]: time="2025-12-29T16:12:25-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:25 music go-librespot[14585]: time="2025-12-29T16:12:25-05:00" level=debug msg="completed challenge" Dec 29 16:12:25 music go-librespot[14585]: time="2025-12-29T16:12:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:25 music go-librespot[14585]: time="2025-12-29T16:12:25-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:25 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:25 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:12:25 music volumio[14300]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 29 16:12:25 music volumio[14300]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 29 16:12:25 music volumio[14300]: info: Streaming services startup Dec 29 16:12:25 music volumio[14300]: info: Starting Streaming Daemon Dec 29 16:12:25 music sudo[14595]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 29 16:12:25 music sudo[14595]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:25 music volumio[14300]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 29 16:12:25 music sudo[14595]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:25 music volumio[14300]: info: Getting Spotify volume Dec 29 16:12:25 music volumio[14300]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:12:25 music volumio[14300]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 16:12:25 music volumio[14300]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 29 16:12:25 music volumio[14300]: errno: -111, Dec 29 16:12:25 music volumio[14300]: code: 'ECONNREFUSED', Dec 29 16:12:25 music volumio[14300]: syscall: 'connect', Dec 29 16:12:25 music volumio[14300]: address: '127.0.0.1', Dec 29 16:12:25 music volumio[14300]: port: 9879, Dec 29 16:12:25 music volumio[14300]: response: undefined Dec 29 16:12:25 music volumio[14300]: } Dec 29 16:12:25 music volumio[14300]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:12:26 music sudo[14630]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 16:11' Dec 29 16:12:26 music sudo[14630]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:26 music sudo[14630]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:26 music volumio-remote-updater[735]: [2025-12-29 21:12:26] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 29 16:12:26 music volumio-remote-updater[735]: [2025-12-29 21:12:26] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 29 16:12:26 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:26 music systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 29 16:12:26 music systemd[1]: volumio.service: Consumed 26.289s CPU time. Dec 29 16:12:26 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:12:26 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:12:26 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 7576. Dec 29 16:12:26 music systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 29 16:12:26 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 29 16:12:26 music systemd[1]: volumio.service: Consumed 26.289s CPU time. Dec 29 16:12:26 music systemd[1]: Started volumio.service - Volumio Backend Module. Dec 29 16:12:26 music systemd[1]: dynamicswap.service: Deactivated successfully. Dec 29 16:12:28 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Dec 29 16:12:28 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:28 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:28 music go-librespot[14658]: go-librespot daemon starting... Dec 29 16:12:28 music go-librespot[14659]: time="2025-12-29T16:12:28-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:28 music go-librespot[14659]: time="2025-12-29T16:12:28-05:00" level=debug msg="app state loaded" Dec 29 16:12:28 music go-librespot[14659]: time="2025-12-29T16:12:28-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:12:28 music volumio[14642]: info: ------------------------------------------- Dec 29 16:12:28 music volumio[14642]: info: ----- Volumio3 ---- Dec 29 16:12:28 music volumio[14642]: info: ------------------------------------------- Dec 29 16:12:28 music volumio[14642]: info: ----- System startup ---- Dec 29 16:12:28 music volumio[14642]: info: ------------------------------------------- Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=info msg="zeroconf server listening on port 37553" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="obtained new client token: AACGVaaJDf7WzR7SrDfMvydRVf168RG1Pj1vj9Gl44N0Olc5IicFig2oNiuAxXu/NyinngVUcRV9DaRn47W8Xbomn79k6Yq3L0myX86QBwkZKt8fbi9cEtQUpBbi6IGzWncrgsEUstk9z1opjCiSBqlA+0sVXdhdKijlvmL4Bal2L3x9hchg5LdTIhM0wmkq5T5aTAQ0tB34meFHOaoNt68v8pvRh4uygsqz60EuwilxQTsEKJEOrA==" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="completed challenge" Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:29 music volumio[14642]: info: MYVOLUMIO Environment detected Dec 29 16:12:29 music volumio[14642]: info: Plugin folders cleanup Dec 29 16:12:29 music volumio[14642]: info: Scanning into folder /volumio/app/plugins/ Dec 29 16:12:29 music volumio[14642]: info: Scanning category audio_interface Dec 29 16:12:29 music volumio[14642]: info: Scanning category miscellanea Dec 29 16:12:29 music volumio[14642]: info: Scanning category music_service Dec 29 16:12:29 music volumio[14642]: info: Scanning category plugins.json Dec 29 16:12:29 music volumio[14642]: info: Scanning category system_controller Dec 29 16:12:29 music volumio[14642]: info: Scanning category user_interface Dec 29 16:12:29 music volumio[14642]: info: Scanning into folder /data/plugins/ Dec 29 16:12:29 music volumio[14642]: info: Scanning category music_service Dec 29 16:12:29 music volumio[14642]: info: Plugin folders cleanup completed Dec 29 16:12:29 music volumio[14642]: info: ------------------------------------------- Dec 29 16:12:29 music volumio[14642]: info: ----- Core plugins startup ---- Dec 29 16:12:29 music volumio[14642]: info: ------------------------------------------- Dec 29 16:12:29 music volumio[14642]: info: Loading plugins from folder /volumio/app/plugins/ Dec 29 16:12:29 music volumio[14642]: info: Adding plugin upnp to MyMusic Plugins Dec 29 16:12:29 music volumio[14642]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 29 16:12:29 music volumio[14642]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 29 16:12:29 music volumio[14642]: info: Loading plugins from folder /data/plugins/ Dec 29 16:12:29 music volumio[14642]: info: Loading plugin "system"... Dec 29 16:12:29 music volumio[14642]: info: Loading plugin "appearance"... Dec 29 16:12:29 music go-librespot[14659]: time="2025-12-29T16:12:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:12:30 music go-librespot[14659]: time="2025-12-29T16:12:30-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:30 music go-librespot[14659]: time="2025-12-29T16:12:30-05:00" level=debug msg="completed challenge" Dec 29 16:12:30 music go-librespot[14659]: time="2025-12-29T16:12:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:30 music go-librespot[14659]: time="2025-12-29T16:12:30-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 29 16:12:30 music go-librespot[14659]: time="2025-12-29T16:12:30-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:30 music go-librespot[14659]: time="2025-12-29T16:12:30-05:00" level=debug msg="completed challenge" Dec 29 16:12:30 music go-librespot[14659]: time="2025-12-29T16:12:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:30 music volumio[14642]: info: Loading plugin "network"... Dec 29 16:12:30 music volumio[14642]: info: Refreshing Cached IP Addresses Dec 29 16:12:31 music sudo[14681]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:12:31 music sudo[14681]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:31 music sudo[14681]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "services"... Dec 29 16:12:31 music sudo[14683]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:12:31 music sudo[14683]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "alsa_controller"... Dec 29 16:12:31 music sudo[14683]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:31 music sudo[14691]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 29 16:12:31 music sudo[14691]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:31 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "wizard"... Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "networkfs"... Dec 29 16:12:31 music volumio[14642]: info: Starting Udev Watcher for removable devices Dec 29 16:12:31 music volumio[14642]: info: Ignoring mount for partition: boot Dec 29 16:12:31 music volumio[14642]: info: Ignoring mount for partition: volumio Dec 29 16:12:31 music volumio[14642]: info: Ignoring mount for partition: volumio_data Dec 29 16:12:31 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "volumio_command_line_client"... Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "upnp"... Dec 29 16:12:31 music volumio[14642]: info: [1767042751213] Starting Upmpd Daemon Dec 29 16:12:31 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "my_music"... Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "mpd"... Dec 29 16:12:31 music go-librespot[14659]: time="2025-12-29T16:12:31-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 29 16:12:31 music volumio[14642]: info: Loading plugin "upnp_browser"... Dec 29 16:12:31 music volumio-remote-updater[735]: [2025-12-29 21:12:31] [connect] Successful connection Dec 29 16:12:31 music sudo[14691]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:31 music go-librespot[14659]: time="2025-12-29T16:12:31-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:31 music go-librespot[14659]: time="2025-12-29T16:12:31-05:00" level=debug msg="completed challenge" Dec 29 16:12:32 music go-librespot[14659]: time="2025-12-29T16:12:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:32 music go-librespot[14659]: time="2025-12-29T16:12:32-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=debug msg="completed challenge" Dec 29 16:12:33 music volumio[14642]: info: Starting UPNP Browser Dec 29 16:12:33 music volumio[14642]: info: Loading plugin "alarm-clock"... Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:33 music volumio[14642]: info: Loading plugin "airplay_emulation"... Dec 29 16:12:33 music volumio[14642]: info: Starting Shairport Sync Dec 29 16:12:33 music volumio[14642]: info: Loading plugin "last_100"... Dec 29 16:12:33 music volumio[14642]: info: Loading plugin "webradio"... Dec 29 16:12:33 music volumio[14642]: info: Loading plugin "i2s_dacs"... Dec 29 16:12:33 music volumio[14642]: info: I2S DAC not set, start Auto-detection Dec 29 16:12:33 music volumio[14642]: info: Loading plugin "volumiodiscovery"... Dec 29 16:12:33 music volumio[14642]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:33 music volumio[14642]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:33 music volumio[14642]: *** WARNING *** For more information see Dec 29 16:12:33 music volumio[14642]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:33 music volumio[14642]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:33 music volumio[14642]: *** WARNING *** For more information see Dec 29 16:12:33 music node[14642]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:33 music node[14642]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:33 music node[14642]: *** WARNING *** For more information see Dec 29 16:12:33 music node[14642]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 29 16:12:33 music node[14642]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 29 16:12:33 music node[14642]: *** WARNING *** For more information see Dec 29 16:12:33 music volumio[14642]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 29 16:12:33 music volumio[14642]: info: Discovery: Started advertising with name: music Dec 29 16:12:33 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 29 16:12:33 music volumio[14642]: info: Loading plugin "spop"... Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=debug msg="completed challenge" Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:33 music go-librespot[14659]: time="2025-12-29T16:12:33-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:33 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:33 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:12:34 music volumio[14642]: info: Loading plugin "outputs"... Dec 29 16:12:34 music volumio[14642]: info: Loading plugin "albumart"... Dec 29 16:12:34 music volumio[14642]: info: Plugin example_plugin is not enabled Dec 29 16:12:34 music volumio[14642]: info: Loading plugin "inputs"... Dec 29 16:12:34 music volumio[14642]: info: Loading plugin "updater_comm"... Dec 29 16:12:34 music volumio[14642]: info: Plugin mpdemulation is not enabled Dec 29 16:12:34 music volumio[14642]: info: Loading plugin "rest_api"... Dec 29 16:12:34 music volumio[14642]: info: Loading plugin "websocket"... Dec 29 16:12:34 music volumio[14642]: info: Starting Socket.io Server version 1.7.4 Dec 29 16:12:34 music volumio[14642]: info: Loading i18n strings for locale en Dec 29 16:12:34 music volumio[14642]: Updating browse sources language Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::initPlayerControls Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:34 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:12:35 music volumio[14642]: Express server listening on port 3000 Dec 29 16:12:35 music volumio[14642]: [Metrics] WebUI: 6s 639.75ms Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::resetVolumioState Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::getcurrentVolume Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:35 music volumio[14642]: info: Volumio Network Manager: Network status updated: 1 Dec 29 16:12:35 music volumio-remote-updater[735]: [2025-12-29 21:12:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1767042751 101 Dec 29 16:12:35 music volumio[14717]: Forking 3 albumart workers Dec 29 16:12:35 music volumio[14642]: 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 29 16:12:35 music volumio[14642]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::pushState Dec 29 16:12:35 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::updateTrackBlock Dec 29 16:12:35 music volumio[14642]: info: CorePlayQueue::getTrackBlock Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioRetrievevolume Dec 29 16:12:35 music volumio[14642]: info: Reloading queue from file Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::setRepeat null single undefined Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::pushState Dec 29 16:12:35 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::setRandom null Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::pushState Dec 29 16:12:35 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:35 music volumio[14642]: info: Setting Device type: Raspberry PI Dec 29 16:12:35 music volumio[14642]: info: VolumeController:: Volume=86 Mute =false Dec 29 16:12:35 music volumio[14642]: info: CoreStateMachine::pushState Dec 29 16:12:35 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioPushState Dec 29 16:12:35 music volumio[14642]: info: Completed loading Core Plugins Dec 29 16:12:35 music volumio[14642]: info: Preparing to generate the ALSA configuration file Dec 29 16:12:35 music volumio[14642]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:12:35 music volumio[14642]: info: Discovery: Found device music Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:35 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:35 music volumio[14642]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Dec 29 16:12:35 music volumio[14642]: info: Discovery: Found device music Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:35 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:35 music volumio[14642]: info: Asound.conf file unchanged, so no further update is needed Dec 29 16:12:35 music volumio[14642]: info: Output device has changed, restarting MPD Dec 29 16:12:35 music volumio[14642]: info: Output device has changed, restarting Shairport Sync Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:35 music volumio[14642]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:12:35 music sudo[14772]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:12:35 music sudo[14772]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:35 music sudo[14774]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:12:35 music sudo[14774]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:35 music volumio[14642]: info: ___________ START PLUGINS ___________ Dec 29 16:12:35 music sudo[14772]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:35 music volumio[14642]: info: ControllerMpd::onStart: Initializing MPD Dec 29 16:12:35 music volumio[14642]: info: Creating MPD Configuration file Dec 29 16:12:35 music systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 29 16:12:35 music sudo[14782]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:12:35 music volumio[14642]: info: [1767042755747] CoreMusicLibrary::Adding element Media Servers Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:35 music sudo[14782]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:35 music sudo[14784]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 29 16:12:35 music sudo[14784]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:35 music sudo[14782]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:35 music volumio[14642]: info: UPNP Browser: Client initialized successfully Dec 29 16:12:35 music systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:12:35 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:12:35 music systemd[1]: mpd.service: Consumed 4.162s CPU time. Dec 29 16:12:35 music systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:12:35 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:12:35 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:35 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:12:35 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:12:35 music volumio[14642]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:35 music systemd[1]: mpd.service: Deactivated successfully. Dec 29 16:12:35 music systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 29 16:12:35 music systemd[1]: mpd.socket: Deactivated successfully. Dec 29 16:12:35 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 29 16:12:35 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 29 16:12:35 music volumio[14642]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:12:35 music volumio[14642]: info: [1767042755992] CoreMusicLibrary::Adding element Last_100 Dec 29 16:12:35 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 29 16:12:35 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:36 music volumio[14642]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 29 16:12:36 music systemd[1]: Starting mpd.service - Music Player Daemon... Dec 29 16:12:36 music volumio[14642]: info: [1767042756010] CoreMusicLibrary::Adding element Webradio Dec 29 16:12:36 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 29 16:12:36 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:12:36 music volumio[14642]: info: Initializing BBC Radios Dec 29 16:12:36 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 29 16:12:36 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:36 music volumio[14642]: info: Creating Spotify config file Dec 29 16:12:36 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:36 music sudo[14798]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 29 16:12:36 music sudo[14798]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 29 16:12:36 music sudo[14798]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:36 music volumio[14642]: info: Volumio Calling Home Dec 29 16:12:36 music volumio[14733]: Starting albumart workers Dec 29 16:12:37 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Dec 29 16:12:37 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:37 music volumio[14734]: Starting albumart workers Dec 29 16:12:37 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:37 music go-librespot[14817]: go-librespot daemon starting... Dec 29 16:12:37 music go-librespot[14818]: time="2025-12-29T16:12:37-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:37 music go-librespot[14818]: time="2025-12-29T16:12:37-05:00" level=info msg="zeroconf server listening on port 39493" Dec 29 16:12:37 music volumio[14642]: info: MPD Permissions set Dec 29 16:12:37 music volumio[14642]: info: MPD Permissions set Dec 29 16:12:37 music volumio[14735]: Starting albumart workers Dec 29 16:12:37 music volumio[14642]: info: Volumio called home Dec 29 16:12:37 music volumio[14642]: info: Spotify config file written Dec 29 16:12:37 music sudo[14829]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 29 16:12:37 music sudo[14829]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:38 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Dec 29 16:12:38 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Dec 29 16:12:38 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:38 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:38 music go-librespot[14837]: go-librespot daemon starting... Dec 29 16:12:38 music sudo[14829]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="app state loaded" Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:12:38 music volumio[14642]: 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 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 29 16:12:38 music volumio[14642]: info: No need to fix Spotify hosts Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=info msg="zeroconf server listening on port 39335" Dec 29 16:12:38 music volumio[14642]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 29 16:12:38 music volumio[14642]: info: Starting Shairport Sync Dec 29 16:12:38 music volumio[14642]: info: Starting Shairport Sync Dec 29 16:12:38 music volumio[14642]: info: Starting Shairport Sync Dec 29 16:12:38 music sudo[14867]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:12:38 music sudo[14867]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:38 music sudo[14871]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:12:38 music sudo[14871]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="obtained new client token: AACIw7NWSvKo+GPLRM2D3xj0QLhRU1WYYqaDzy1skcp7paa/YwCXLfcoJUuah1NrKtXItc2xW8w+cc2fyLiPfcclNIOJpXu6NackUgHJ7/cb5s9XGtz7XfL/TQarSgrg0w5bkaEiF2NnLvdZMyE6rPjaa+3wQv4LOoCtQGWM6vlKfi37k2qXe/RGlgAhMBsjnxMktOiznaLKNU3rB1fAjmGIF5JBPENR5ilEwauMeLxVm0uF7c9ZaasI" Dec 29 16:12:38 music sudo[14870]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 29 16:12:38 music sudo[14870]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:38 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 29 16:12:38 music systemd[1]: shairport-sync.service: Deactivated successfully. Dec 29 16:12:38 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:12:38 music systemd[1]: shairport-sync.service: Consumed 1.766s CPU time. Dec 29 16:12:38 music volumio[14642]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:38 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=debug msg="completed challenge" Dec 29 16:12:38 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 29 16:12:38 music sudo[14871]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:38 music sudo[14867]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:38 music go-librespot[14839]: time="2025-12-29T16:12:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:38 music sudo[14870]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:38 music volumio[14642]: info: Shairport-Sync Started Dec 29 16:12:39 music volumio[14642]: Error adding Membership: Error: addMembership EINVAL Dec 29 16:12:39 music volumio[14642]: info: Shairport-Sync Started Dec 29 16:12:39 music volumio[14642]: info: Shairport-Sync Started Dec 29 16:12:39 music go-librespot[14839]: time="2025-12-29T16:12:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:12:39 music go-librespot[14839]: time="2025-12-29T16:12:39-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:39 music go-librespot[14839]: time="2025-12-29T16:12:39-05:00" level=debug msg="completed challenge" Dec 29 16:12:39 music go-librespot[14839]: time="2025-12-29T16:12:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:40 music go-librespot[14839]: time="2025-12-29T16:12:40-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:12:40 music go-librespot[14839]: time="2025-12-29T16:12:40-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:40 music go-librespot[14839]: time="2025-12-29T16:12:40-05:00" level=debug msg="completed challenge" Dec 29 16:12:40 music go-librespot[14839]: time="2025-12-29T16:12:40-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:40 music mpd[14813]: 2025-12-29T16:12:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 29 16:12:40 music systemd[1]: Started mpd.service - Music Player Daemon. Dec 29 16:12:40 music sudo[14784]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:40 music sudo[14774]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:40 music volumio[14642]: info: Completed starting Core Plugins Dec 29 16:12:40 music volumio[14642]: info: ------------------------------------------- Dec 29 16:12:40 music volumio[14642]: info: ----- MyVolumio plugins startup ---- Dec 29 16:12:40 music volumio[14642]: info: ------------------------------------------- Dec 29 16:12:40 music volumio[14642]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 29 16:12:40 music volumio[14642]: error: MPD error: The expression evaluated to a falsy value: Dec 29 16:12:40 music volumio[14642]: assert.ok(self.idling) Dec 29 16:12:40 music volumio[14642]: error: The expression evaluated to a falsy value: Dec 29 16:12:40 music volumio[14642]: assert.ok(self.idling) Dec 29 16:12:40 music volumio[14642]: error: updateQueue error: null Dec 29 16:12:40 music volumio[14642]: info: MPD running with PID14813 Dec 29 16:12:40 music volumio[14642]: ,establishing connection Dec 29 16:12:40 music volumio[14642]: error: updateQueue error: null Dec 29 16:12:40 music go-librespot[14839]: time="2025-12-29T16:12:40-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 29 16:12:40 music go-librespot[14839]: time="2025-12-29T16:12:40-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:40 music go-librespot[14839]: time="2025-12-29T16:12:40-05:00" level=debug msg="completed challenge" Dec 29 16:12:41 music go-librespot[14839]: time="2025-12-29T16:12:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:41 music sudo[14917]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 29 16:12:41 music sudo[14917]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:41 music sudo[14919]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 29 16:12:41 music sudo[14917]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:41 music sudo[14919]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:41 music sudo[14919]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:41 music sudo[14922]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 29 16:12:41 music sudo[14922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:41 music sudo[14922]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:41 music volumio[14642]: info: Upmpdcli Daemon Started Dec 29 16:12:41 music volumio[14642]: info: go-librespot daemon successfully initialized Dec 29 16:12:41 music go-librespot[14839]: time="2025-12-29T16:12:41-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 29 16:12:41 music go-librespot[14839]: time="2025-12-29T16:12:41-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:41 music go-librespot[14839]: time="2025-12-29T16:12:41-05:00" level=debug msg="completed challenge" Dec 29 16:12:42 music go-librespot[14839]: time="2025-12-29T16:12:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:42 music go-librespot[14839]: time="2025-12-29T16:12:42-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Dec 29 16:12:42 music go-librespot[14839]: time="2025-12-29T16:12:42-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:42 music go-librespot[14839]: time="2025-12-29T16:12:42-05:00" level=debug msg="completed challenge" Dec 29 16:12:43 music go-librespot[14839]: time="2025-12-29T16:12:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:43 music go-librespot[14839]: time="2025-12-29T16:12:43-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:43 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:43 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:12:43 music sudo[14926]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:12:43 music sudo[14926]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:43 music sudo[14928]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 29 16:12:43 music sudo[14928]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:43 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 29 16:12:43 music systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 29 16:12:43 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 29 16:12:43 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 29 16:12:43 music sudo[14926]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:43 music mpd_monitor.sh[14931]: MPD Monitor Service: Starting MPD Monitor Service Dec 29 16:12:43 music sudo[14928]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:43 music volumio[14642]: info: Successfully started MPD Monitor Dec 29 16:12:43 music volumio[14642]: info: Successfully started MPD Monitor Dec 29 16:12:44 music volumio[14642]: info: Initializing connection to go-librespot Websocket Dec 29 16:12:44 music volumio[14642]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 29 16:12:45 music volumio[14642]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 29 16:12:46 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Dec 29 16:12:46 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:46 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 29 16:12:46 music go-librespot[14935]: go-librespot daemon starting... Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=info msg="running go-librespot 0.6.2" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="app state loaded" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=info msg="zeroconf server listening on port 36731" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="obtained new client token: AACiduzPRMkhlpz942kbYwzcC+P7ksz7C/pL9JGp+y5dBOnzWMeXoEEgpyWoqciwyJQ5bdRZG4FNcbpzKs6iyQmsMMg8inCzi/uhiZFDXIWValCXinpnpFtPi0aHvpeoIkPTjnM6PRT+6/3z/SCDpu98AfJOPiCoZgTnFePvS68jOG53QZ0n/52jrnKqpDkn/lI5Yi6ER5is1L4t2QjOth3zdLWGYO+sg5VPx27acfZ7wqvBZ8up4CYh" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=debug msg="completed challenge" Dec 29 16:12:46 music go-librespot[14936]: time="2025-12-29T16:12:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:47 music go-librespot[14936]: time="2025-12-29T16:12:47-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 29 16:12:47 music go-librespot[14936]: time="2025-12-29T16:12:47-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:47 music go-librespot[14936]: time="2025-12-29T16:12:47-05:00" level=debug msg="completed challenge" Dec 29 16:12:47 music go-librespot[14936]: time="2025-12-29T16:12:47-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:47 music volumio[14642]: info: Initializing connection to go-librespot Websocket Dec 29 16:12:47 music go-librespot[14936]: time="2025-12-29T16:12:47-05:00" level=debug msg="new websocket client" Dec 29 16:12:47 music volumio[14642]: info: Connection to go-librespot Websocket established Dec 29 16:12:48 music go-librespot[14936]: time="2025-12-29T16:12:48-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 29 16:12:48 music go-librespot[14936]: time="2025-12-29T16:12:48-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:48 music go-librespot[14936]: time="2025-12-29T16:12:48-05:00" level=debug msg="completed challenge" Dec 29 16:12:48 music go-librespot[14936]: time="2025-12-29T16:12:48-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:48 music go-librespot[14936]: time="2025-12-29T16:12:48-05: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 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 29 16:12:48 music volumio[14642]: info: Adding plugin bluetooth to MyMusic Plugins Dec 29 16:12:48 music volumio[14642]: info: Adding plugin multiroom to MyMusic Plugins Dec 29 16:12:48 music volumio[14642]: info: Adding plugin metavolumio to MyMusic Plugins Dec 29 16:12:48 music volumio[14642]: info: Adding plugin cd_controller to MyMusic Plugins Dec 29 16:12:48 music volumio[14642]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 29 16:12:48 music volumio[14642]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 29 16:12:48 music volumio[14642]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 29 16:12:48 music volumio[14642]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 29 16:12:48 music go-librespot[14936]: time="2025-12-29T16:12:48-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Dec 29 16:12:49 music go-librespot[14936]: time="2025-12-29T16:12:49-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:49 music go-librespot[14936]: time="2025-12-29T16:12:49-05:00" level=debug msg="completed challenge" Dec 29 16:12:49 music go-librespot[14936]: time="2025-12-29T16:12:49-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:49 music volumio[14642]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 29 16:12:49 music volumio[14642]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 29 16:12:49 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:49 music volumio[14642]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 29 16:12:49 music volumio[14642]: info: Starting MyVolumio Remote Streaming Endpoints Dec 29 16:12:49 music volumio[14642]: info: MyVolumio login type: Token Dec 29 16:12:49 music volumio[14642]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 29 16:12:49 music volumio[14642]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 29 16:12:50 music go-librespot[14936]: time="2025-12-29T16:12:50-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Dec 29 16:12:50 music go-librespot[14936]: time="2025-12-29T16:12:50-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:50 music go-librespot[14936]: time="2025-12-29T16:12:50-05:00" level=debug msg="completed challenge" Dec 29 16:12:50 music go-librespot[14936]: time="2025-12-29T16:12:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:50 music volumio[14642]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 29 16:12:50 music volumio[14642]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 29 16:12:50 music volumio[14642]: info: Streaming services startup Dec 29 16:12:50 music volumio[14642]: info: Starting Streaming Daemon Dec 29 16:12:50 music sudo[14946]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 29 16:12:50 music sudo[14946]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 29 16:12:50 music volumio[14642]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 29 16:12:50 music sudo[14946]: pam_unix(sudo:session): session closed for user root Dec 29 16:12:50 music volumio[14642]: info: Getting Spotify volume Dec 29 16:12:50 music volumio[14642]: error: Cannot start Volumio Streaming Daemon Dec 29 16:12:50 music volumio[14642]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 29 16:12:50 music volumio[14642]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 29 16:12:50 music volumio[14642]: 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 29 16:12:51 music volumio[14642]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:51 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:51 music volumio[14642]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 29 16:12:51 music volumio[14642]: SPOTIFY: SPOTIFY VOLUME undefined Dec 29 16:12:51 music volumio[14642]: SPOTIFY: VOLUMIO VOLUME 86 Dec 29 16:12:51 music volumio[14642]: info: Aligning Spotify Volume to Volumio Volume Dec 29 16:12:51 music volumio[14642]: info: CoreCommandRouter::volumioGetState Dec 29 16:12:51 music volumio[14642]: info: CorePlayQueue::getTrack 0 Dec 29 16:12:51 music volumio[14642]: info: Setting Spotify Volume from Volumio: 86 Dec 29 16:12:51 music go-librespot[14936]: time="2025-12-29T16:12:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 29 16:12:51 music go-librespot[14936]: time="2025-12-29T16:12:51-05:00" level=debug msg="completed keyexchange" Dec 29 16:12:51 music go-librespot[14936]: time="2025-12-29T16:12:51-05:00" level=debug msg="completed challenge" Dec 29 16:12:51 music go-librespot[14936]: time="2025-12-29T16:12:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:51 music go-librespot[14936]: time="2025-12-29T16:12:51-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 29 16:12:51 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 29 16:12:51 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 29 16:12:51 music volumio[14642]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 29 16:12:51 music volumio[14642]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:12:51 music volumio[14642]: Error: socket hang up Dec 29 16:12:51 music volumio[14642]: at connResetException (node:internal/errors:720:14) Dec 29 16:12:51 music volumio[14642]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 29 16:12:51 music volumio[14642]: at Socket.emit (node:events:526:35) Dec 29 16:12:51 music volumio[14642]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 29 16:12:51 music volumio[14642]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 29 16:12:51 music volumio[14642]: code: 'ECONNRESET', Dec 29 16:12:51 music volumio[14642]: response: undefined Dec 29 16:12:51 music volumio[14642]: } Dec 29 16:12:51 music volumio[14642]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 29 16:12:52 music sudo[14980]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-29 16:11' Dec 29 16:12:52 music sudo[14980]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"