Jan 10 23:41:00 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 10 23:41:00 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:00 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:00 music go-librespot[32207]: go-librespot daemon starting... Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=debug msg="app state loaded" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-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]" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-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]" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=info msg="zeroconf server listening on port 39395" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=debug msg="obtained new client token: AADYG32cQsLUzrrOMhOzJ1jGEy6EPRSChGqXyDLzcqg2jiZ1t3hgWHlMLBlY1woeAI59TCDa3UoUtGcUyVxP8rEGXJLrfgAtcoi0Dxr27GRi8GBrrS6Gl1J0xOGLF92EJqdWnKKVqa34l1A6t94mfR8xmU0j6HPz4aLs2Ib7rEearJPlHnRNa67d5NR8CiKguQK7puQVg1MtZDzD+OVw0nIk6xPLMBwUnTIu+g3o7GSJ0rz13RI3qxg=" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:00 music go-librespot[32208]: time="2026-01-10T23:41:00-05:00" level=debug msg="completed challenge" Jan 10 23:41:01 music go-librespot[32208]: time="2026-01-10T23:41:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:01 music volumio-remote-updater[22000]: [2026-01-10 23:41:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 23:41:01 music volumio-remote-updater[22000]: [2026-01-10 23:41:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 23:41:01 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:01 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 23:41:01 music systemd[1]: volumio.service: Consumed 26.626s CPU time. Jan 10 23:41:01 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:41:01 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:41:01 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4335. Jan 10 23:41:01 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:41:01 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 23:41:01 music systemd[1]: volumio.service: Consumed 26.626s CPU time. Jan 10 23:41:01 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 23:41:01 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:41:01 music go-librespot[32208]: time="2026-01-10T23:41:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:01 music go-librespot[32208]: time="2026-01-10T23:41:01-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:01 music go-librespot[32208]: time="2026-01-10T23:41:01-05:00" level=debug msg="completed challenge" Jan 10 23:41:01 music go-librespot[32208]: time="2026-01-10T23:41:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:02 music go-librespot[32208]: time="2026-01-10T23:41:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:41:02 music go-librespot[32208]: time="2026-01-10T23:41:02-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:02 music go-librespot[32208]: time="2026-01-10T23:41:02-05:00" level=debug msg="completed challenge" Jan 10 23:41:02 music go-librespot[32208]: time="2026-01-10T23:41:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:03 music go-librespot[32208]: time="2026-01-10T23:41:03-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 10 23:41:03 music volumio[32224]: info: ------------------------------------------- Jan 10 23:41:03 music volumio[32224]: info: ----- Volumio3 ---- Jan 10 23:41:03 music volumio[32224]: info: ------------------------------------------- Jan 10 23:41:03 music volumio[32224]: info: ----- System startup ---- Jan 10 23:41:03 music volumio[32224]: info: ------------------------------------------- Jan 10 23:41:03 music go-librespot[32208]: time="2026-01-10T23:41:03-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:03 music go-librespot[32208]: time="2026-01-10T23:41:03-05:00" level=debug msg="completed challenge" Jan 10 23:41:03 music go-librespot[32208]: time="2026-01-10T23:41:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:04 music volumio[32224]: info: MYVOLUMIO Environment detected Jan 10 23:41:04 music volumio[32224]: info: Plugin folders cleanup Jan 10 23:41:04 music volumio[32224]: info: Scanning into folder /volumio/app/plugins/ Jan 10 23:41:04 music volumio[32224]: info: Scanning category audio_interface Jan 10 23:41:04 music volumio[32224]: info: Scanning category miscellanea Jan 10 23:41:04 music volumio[32224]: info: Scanning category music_service Jan 10 23:41:04 music volumio[32224]: info: Scanning category plugins.json Jan 10 23:41:04 music volumio[32224]: info: Scanning category system_controller Jan 10 23:41:04 music volumio[32224]: info: Scanning category user_interface Jan 10 23:41:04 music volumio[32224]: info: Scanning into folder /data/plugins/ Jan 10 23:41:04 music volumio[32224]: info: Scanning category music_service Jan 10 23:41:04 music volumio[32224]: info: Plugin folders cleanup completed Jan 10 23:41:04 music volumio[32224]: info: ------------------------------------------- Jan 10 23:41:04 music volumio[32224]: info: ----- Core plugins startup ---- Jan 10 23:41:04 music volumio[32224]: info: ------------------------------------------- Jan 10 23:41:04 music volumio[32224]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 23:41:04 music volumio[32224]: info: Adding plugin upnp to MyMusic Plugins Jan 10 23:41:04 music volumio[32224]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 23:41:04 music volumio[32224]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 23:41:04 music volumio[32224]: info: Loading plugins from folder /data/plugins/ Jan 10 23:41:04 music volumio[32224]: info: Loading plugin "system"... Jan 10 23:41:04 music volumio[32224]: info: Loading plugin "appearance"... Jan 10 23:41:04 music go-librespot[32208]: time="2026-01-10T23:41:04-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 10 23:41:04 music go-librespot[32208]: time="2026-01-10T23:41:04-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:04 music go-librespot[32208]: time="2026-01-10T23:41:04-05:00" level=debug msg="completed challenge" Jan 10 23:41:04 music go-librespot[32208]: time="2026-01-10T23:41:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:05 music go-librespot[32208]: time="2026-01-10T23:41:05-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 10 23:41:05 music go-librespot[32208]: time="2026-01-10T23:41:05-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:05 music go-librespot[32208]: time="2026-01-10T23:41:05-05:00" level=debug msg="completed challenge" Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "network"... Jan 10 23:41:05 music volumio[32224]: info: Refreshing Cached IP Addresses Jan 10 23:41:05 music sudo[32252]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:41:05 music sudo[32252]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:05 music sudo[32254]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:41:05 music sudo[32252]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:05 music sudo[32254]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "services"... Jan 10 23:41:05 music sudo[32254]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "alsa_controller"... Jan 10 23:41:05 music go-librespot[32208]: time="2026-01-10T23:41:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:05 music go-librespot[32208]: time="2026-01-10T23:41: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 " Jan 10 23:41:05 music sudo[32262]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 23:41:05 music sudo[32262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:05 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:05 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:41:05 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "wizard"... Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "networkfs"... Jan 10 23:41:05 music volumio[32224]: info: Starting Udev Watcher for removable devices Jan 10 23:41:05 music volumio[32224]: info: Ignoring mount for partition: boot Jan 10 23:41:05 music volumio[32224]: info: Ignoring mount for partition: volumio Jan 10 23:41:05 music volumio[32224]: info: Ignoring mount for partition: volumio_data Jan 10 23:41:05 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "volumio_command_line_client"... Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "upnp"... Jan 10 23:41:05 music volumio[32224]: info: [1768106465839] Starting Upmpd Daemon Jan 10 23:41:05 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "my_music"... Jan 10 23:41:05 music volumio[32224]: info: Loading plugin "mpd"... Jan 10 23:41:06 music volumio[32224]: info: Loading plugin "upnp_browser"... Jan 10 23:41:06 music sudo[32262]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:06 music volumio-remote-updater[22000]: [2026-01-10 23:41:06] [connect] Successful connection Jan 10 23:41:07 music volumio[32224]: info: Starting UPNP Browser Jan 10 23:41:07 music volumio[32224]: info: Loading plugin "alarm-clock"... Jan 10 23:41:07 music volumio[32224]: info: Loading plugin "airplay_emulation"... Jan 10 23:41:07 music volumio[32224]: info: Starting Shairport Sync Jan 10 23:41:07 music volumio[32224]: info: Loading plugin "last_100"... Jan 10 23:41:07 music volumio[32224]: info: Loading plugin "webradio"... Jan 10 23:41:08 music volumio[32224]: info: Loading plugin "i2s_dacs"... Jan 10 23:41:08 music volumio[32224]: info: I2S DAC not set, start Auto-detection Jan 10 23:41:08 music volumio[32224]: info: Loading plugin "volumiodiscovery"... Jan 10 23:41:08 music volumio[32224]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:08 music volumio[32224]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:08 music volumio[32224]: *** WARNING *** For more information see Jan 10 23:41:08 music volumio[32224]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:08 music volumio[32224]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:08 music volumio[32224]: *** WARNING *** For more information see Jan 10 23:41:08 music node[32224]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:08 music node[32224]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:08 music node[32224]: *** WARNING *** For more information see Jan 10 23:41:08 music node[32224]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:08 music node[32224]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:08 music node[32224]: *** WARNING *** For more information see Jan 10 23:41:08 music volumio[32224]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 23:41:08 music volumio[32224]: info: Discovery: Started advertising with name: music Jan 10 23:41:08 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:08 music volumio[32224]: info: Loading plugin "spop"... Jan 10 23:41:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 10 23:41:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:08 music go-librespot[32287]: go-librespot daemon starting... Jan 10 23:41:08 music go-librespot[32288]: time="2026-01-10T23:41:08-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:08 music go-librespot[32288]: time="2026-01-10T23:41:08-05:00" level=debug msg="app state loaded" Jan 10 23:41:08 music go-librespot[32288]: time="2026-01-10T23:41:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:09 music volumio[32224]: info: Loading plugin "outputs"... Jan 10 23:41:09 music volumio[32224]: info: Loading plugin "albumart"... Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-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]" Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-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]" Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-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]" Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-05:00" level=info msg="zeroconf server listening on port 37899" Jan 10 23:41:09 music volumio[32224]: info: Plugin example_plugin is not enabled Jan 10 23:41:09 music volumio[32224]: info: Loading plugin "inputs"... Jan 10 23:41:09 music volumio[32224]: info: Loading plugin "updater_comm"... Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-05:00" level=debug msg="obtained new client token: AACfW9ZVwdlXB5oAIT7qzIP1uKrhm03AWMXTEi2r/0Bsa9LrbM3Bvhk07M6SIhTnShRXLpP3y7tWftNa0NVGmzPDGdldH8L36jph+9r+/uhs+1Zh8r73T5JFVCBAuHKp/PZCZ5Ylfu08HZcFTot5MFoJed0Gtjz4XAF1d4NKilI54l77plCvE5MHiAb+tf6Ix+sAvciC+V4fFmoArO5FA0qEcnuO+iQ0BVW2O7OkyDiNowQLBS+k1GQ=" Jan 10 23:41:09 music volumio[32224]: info: Plugin mpdemulation is not enabled Jan 10 23:41:09 music volumio[32224]: info: Loading plugin "rest_api"... Jan 10 23:41:09 music volumio[32224]: info: Loading plugin "websocket"... Jan 10 23:41:09 music volumio[32224]: info: Starting Socket.io Server version 1.7.4 Jan 10 23:41:09 music volumio[32224]: info: Loading i18n strings for locale en Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:09 music volumio[32224]: Updating browse sources language Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-05:00" level=debug msg="completed challenge" Jan 10 23:41:09 music go-librespot[32288]: time="2026-01-10T23:41:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::initPlayerControls Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:09 music volumio[32224]: Express server listening on port 3000 Jan 10 23:41:09 music volumio[32224]: [Metrics] WebUI: 6s 641.84ms Jan 10 23:41:09 music volumio[32224]: info: CoreStateMachine::resetVolumioState Jan 10 23:41:09 music volumio[32224]: info: CoreStateMachine::getcurrentVolume Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:09 music volumio[32224]: info: Volumio Network Manager: Network status updated: 1 Jan 10 23:41:09 music volumio-remote-updater[22000]: [2026-01-10 23:41:09] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768106466 101 Jan 10 23:41:09 music volumio[32224]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 10 23:41:09 music volumio[32297]: Forking 3 albumart workers Jan 10 23:41:09 music volumio[32224]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:41:09 music volumio[32224]: info: CoreStateMachine::pushState Jan 10 23:41:09 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:09 music volumio[32224]: info: CoreStateMachine::updateTrackBlock Jan 10 23:41:09 music volumio[32224]: info: CorePlayQueue::getTrackBlock Jan 10 23:41:09 music volumio[32224]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:41:10 music volumio[32224]: info: Reloading queue from file Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:10 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:10 music volumio[32224]: info: CoreStateMachine::setRepeat null single undefined Jan 10 23:41:10 music volumio[32224]: info: CoreStateMachine::pushState Jan 10 23:41:10 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:10 music volumio[32224]: info: CoreStateMachine::setRandom null Jan 10 23:41:10 music volumio[32224]: info: CoreStateMachine::pushState Jan 10 23:41:10 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:10 music volumio[32224]: info: Setting Device type: Raspberry PI Jan 10 23:41:10 music volumio[32224]: info: Listing playlists Jan 10 23:41:10 music volumio[32224]: info: Listing playlists Jan 10 23:41:10 music go-librespot[32288]: time="2026-01-10T23:41:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:10 music volumio[32224]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:41:10 music volumio[32224]: info: CoreStateMachine::pushState Jan 10 23:41:10 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:10 music volumio[32224]: info: Completed loading Core Plugins Jan 10 23:41:10 music volumio[32224]: info: Preparing to generate the ALSA configuration file Jan 10 23:41:10 music volumio[32224]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:41:10 music volumio[32224]: info: Discovery: Found device music Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:10 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:10 music go-librespot[32288]: time="2026-01-10T23:41:10-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:10 music go-librespot[32288]: time="2026-01-10T23:41:10-05:00" level=debug msg="completed challenge" Jan 10 23:41:10 music volumio[32224]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:41:10 music volumio[32224]: info: Discovery: Found device music Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:10 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:10 music volumio[32224]: info: Asound.conf file unchanged, so no further update is needed Jan 10 23:41:10 music volumio[32224]: info: Output device has changed, restarting MPD Jan 10 23:41:10 music volumio[32224]: info: Output device has changed, restarting Shairport Sync Jan 10 23:41:10 music go-librespot[32288]: time="2026-01-10T23:41:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:10 music sudo[32357]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:41:10 music sudo[32357]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:10 music sudo[32355]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:41:10 music sudo[32355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:10 music sudo[32355]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:10 music volumio[32224]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:10 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 23:41:10 music volumio[32224]: info: ___________ START PLUGINS ___________ Jan 10 23:41:10 music systemd[1]: mpd.service: Deactivated successfully. Jan 10 23:41:10 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 23:41:10 music volumio[32224]: info: ControllerMpd::onStart: Initializing MPD Jan 10 23:41:10 music systemd[1]: mpd.service: Consumed 4.078s CPU time. Jan 10 23:41:10 music volumio[32224]: info: Creating MPD Configuration file Jan 10 23:41:10 music systemd[1]: mpd.socket: Deactivated successfully. Jan 10 23:41:10 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 23:41:10 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:10 music sudo[32366]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:10 music volumio[32224]: info: [1768106470650] CoreMusicLibrary::Adding element Media Servers Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:10 music sudo[32366]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:10 music sudo[32366]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:10 music sudo[32368]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:41:10 music sudo[32368]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:10 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 23:41:10 music volumio[32224]: info: UPNP Browser: Client initialized successfully Jan 10 23:41:10 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:10 music systemd[1]: mpd.service: Deactivated successfully. Jan 10 23:41:10 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 23:41:10 music systemd[1]: mpd.socket: Deactivated successfully. Jan 10 23:41:10 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 23:41:10 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 23:41:10 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 23:41:10 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 23:41:10 music volumio[32224]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:10 music volumio[32224]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:10 music volumio[32224]: info: [1768106470882] CoreMusicLibrary::Adding element Last_100 Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:10 music volumio[32224]: info: [1768106470887] CoreMusicLibrary::Adding element Webradio Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:10 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:10 music volumio[32224]: info: Initializing BBC Radios Jan 10 23:41:11 music go-librespot[32288]: time="2026-01-10T23:41:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:41:11 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:11 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:11 music sudo[32377]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 23:41:11 music sudo[32377]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 23:41:11 music go-librespot[32288]: time="2026-01-10T23:41:11-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:11 music go-librespot[32288]: time="2026-01-10T23:41:11-05:00" level=debug msg="completed challenge" Jan 10 23:41:11 music volumio[32224]: info: Creating Spotify config file Jan 10 23:41:11 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:11 music sudo[32377]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:11 music go-librespot[32288]: time="2026-01-10T23:41:11-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:11 music volumio[32224]: info: Volumio Calling Home Jan 10 23:41:11 music volumio[32313]: Starting albumart workers Jan 10 23:41:11 music go-librespot[32288]: time="2026-01-10T23:41:11-05:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Jan 10 23:41:11 music volumio[32315]: Starting albumart workers Jan 10 23:41:12 music volumio[32314]: Starting albumart workers Jan 10 23:41:12 music go-librespot[32288]: time="2026-01-10T23:41:12-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:12 music go-librespot[32288]: time="2026-01-10T23:41:12-05:00" level=debug msg="completed challenge" Jan 10 23:41:12 music volumio[32224]: info: MPD Permissions set Jan 10 23:41:12 music volumio[32224]: info: MPD Permissions set Jan 10 23:41:12 music go-librespot[32288]: time="2026-01-10T23:41:12-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:12 music volumio[32224]: info: Volumio called home Jan 10 23:41:12 music volumio[32224]: info: Spotify config file written Jan 10 23:41:12 music sudo[32402]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:41:12 music sudo[32402]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:12 music volumio[32224]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:12 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:12 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:41:12 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:12 music volumio[32224]: info: No need to fix Spotify hosts Jan 10 23:41:12 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:12 music go-librespot[32414]: go-librespot daemon starting... Jan 10 23:41:12 music sudo[32402]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:12 music go-librespot[32415]: time="2026-01-10T23:41:12-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:12 music go-librespot[32415]: time="2026-01-10T23:41:12-05:00" level=debug msg="app state loaded" Jan 10 23:41:12 music go-librespot[32415]: time="2026-01-10T23:41:12-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-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]" Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-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]" Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-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]" Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-05:00" level=info msg="zeroconf server listening on port 42075" Jan 10 23:41:13 music volumio[32224]: info: Starting Shairport Sync Jan 10 23:41:13 music volumio[32224]: info: Starting Shairport Sync Jan 10 23:41:13 music volumio[32224]: info: Starting Shairport Sync Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-05:00" level=debug msg="obtained new client token: AABe2fyUvJBQAkfVvR0VSPPTNzdCrrfNKhSPl58k8qA4rQfVi5RLktyxPiETaz4qf3RhNvsFPEz/7zvlZvumJItIcIBtfTnbDDAjy/1mmYqizSs7k2zTarSm8e0ub+9vtlI01mhDuKC+paeLLlfGS7bqKF1DkGvqenHzfcRopngwNzHsjWe2IcJXw/jOlatO2yJEELECl/51o/lzOC7nCKMlGP6usKcl9+YzKYpxiKKsMK86GdRTJAg=" Jan 10 23:41:13 music sudo[32445]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:41:13 music sudo[32445]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:13 music volumio[32224]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 10 23:41:13 music sudo[32443]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:41:13 music sudo[32443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:13 music sudo[32448]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:41:13 music sudo[32448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:13 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 23:41:13 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 23:41:13 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:13 music systemd[1]: shairport-sync.service: Consumed 1.849s CPU time. Jan 10 23:41:13 music volumio[32224]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:13 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-05:00" level=debug msg="completed challenge" Jan 10 23:41:13 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:13 music sudo[32443]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:13 music sudo[32445]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:13 music volumio[32224]: info: Shairport-Sync Started Jan 10 23:41:13 music volumio[32224]: Error adding Membership: Error: addMembership EINVAL Jan 10 23:41:13 music volumio[32224]: info: Shairport-Sync Started Jan 10 23:41:13 music go-librespot[32415]: time="2026-01-10T23:41:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:13 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 23:41:13 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 23:41:13 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:13 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:13 music sudo[32448]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:13 music volumio[32224]: info: Shairport-Sync Started Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=debug msg="completed challenge" Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=debug msg="completed challenge" Jan 10 23:41:14 music go-librespot[32415]: time="2026-01-10T23:41:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:15 music mpd[32396]: 2026-01-10T23:41:15 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 23:41:15 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 23:41:15 music sudo[32368]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:15 music sudo[32357]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:15 music volumio[32224]: info: Completed starting Core Plugins Jan 10 23:41:15 music volumio[32224]: info: ------------------------------------------- Jan 10 23:41:15 music volumio[32224]: info: ----- MyVolumio plugins startup ---- Jan 10 23:41:15 music volumio[32224]: info: ------------------------------------------- Jan 10 23:41:15 music volumio[32224]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 10 23:41:15 music volumio[32224]: error: MPD error: The expression evaluated to a falsy value: Jan 10 23:41:15 music volumio[32224]: assert.ok(self.idling) Jan 10 23:41:15 music volumio[32224]: error: The expression evaluated to a falsy value: Jan 10 23:41:15 music volumio[32224]: assert.ok(self.idling) Jan 10 23:41:15 music volumio[32224]: info: MPD running with PID32396 Jan 10 23:41:15 music volumio[32224]: ,establishing connection Jan 10 23:41:15 music volumio[32224]: error: updateQueue error: null Jan 10 23:41:15 music volumio[32224]: error: updateQueue error: null Jan 10 23:41:15 music go-librespot[32415]: time="2026-01-10T23:41:15-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" Jan 10 23:41:15 music go-librespot[32415]: time="2026-01-10T23:41:15-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:41:15 music sudo[32487]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:41:15 music sudo[32487]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:15 music sudo[32487]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:15 music sudo[32489]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:41:15 music sudo[32489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:15 music sudo[32489]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:15 music sudo[32492]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 23:41:15 music sudo[32492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:15 music sudo[32492]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:15 music volumio[32224]: info: Upmpdcli Daemon Started Jan 10 23:41:15 music go-librespot[32415]: time="2026-01-10T23:41:15-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:15 music go-librespot[32415]: time="2026-01-10T23:41:15-05:00" level=debug msg="completed challenge" Jan 10 23:41:16 music go-librespot[32415]: time="2026-01-10T23:41:16-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:16 music volumio[32224]: info: go-librespot daemon successfully initialized Jan 10 23:41:16 music go-librespot[32415]: time="2026-01-10T23:41:16-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 10 23:41:16 music go-librespot[32415]: time="2026-01-10T23:41:16-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:16 music go-librespot[32415]: time="2026-01-10T23:41:16-05:00" level=debug msg="completed challenge" Jan 10 23:41:17 music go-librespot[32415]: time="2026-01-10T23:41:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:17 music go-librespot[32415]: time="2026-01-10T23:41:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:17 music go-librespot[32415]: time="2026-01-10T23:41:17-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:17 music go-librespot[32415]: time="2026-01-10T23:41:17-05:00" level=debug msg="completed challenge" Jan 10 23:41:17 music go-librespot[32415]: time="2026-01-10T23:41:17-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:17 music go-librespot[32415]: time="2026-01-10T23:41: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 " Jan 10 23:41:17 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:17 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:41:18 music sudo[32496]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:41:18 music sudo[32496]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:18 music sudo[32498]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:41:18 music sudo[32498]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:18 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 23:41:18 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 23:41:18 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 23:41:18 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 23:41:18 music sudo[32498]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:18 music sudo[32496]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:18 music mpd_monitor.sh[32501]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 23:41:18 music volumio[32224]: info: Successfully started MPD Monitor Jan 10 23:41:18 music volumio[32224]: info: Successfully started MPD Monitor Jan 10 23:41:19 music volumio[32224]: info: Initializing connection to go-librespot Websocket Jan 10 23:41:19 music volumio[32224]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 23:41:19 music volumio[32224]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:19 music volumio[32224]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:20 music volumio[32224]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 10 23:41:20 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 10 23:41:20 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:20 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:20 music go-librespot[32505]: go-librespot daemon starting... Jan 10 23:41:20 music go-librespot[32506]: time="2026-01-10T23:41:20-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:20 music go-librespot[32506]: time="2026-01-10T23:41:20-05:00" level=debug msg="app state loaded" Jan 10 23:41:20 music go-librespot[32506]: time="2026-01-10T23:41:20-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-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]" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-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]" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-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]" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-05:00" level=info msg="zeroconf server listening on port 35577" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-05:00" level=debug msg="obtained new client token: AACh6Q1+rLqtnDqU0Vfa96N56fYs1t2PHPcHoS/hcTnHLHAh7s0vmKAOINtf099QoIqCCXdzvqEmn8J0g5LTZp8lOyQ72/RTDsOG7Engck3aBeqzdHe5/NNUS2Ko4OXokN1e9ikNFWlGH6HBzywLPcO6ZCQIfQN3g0eORuKmHb3Jh5OHHsAX2h4m/k7KJGldkM/0nqbQKYauRGrmMKl47sCHVvIRS63FNnABUzz/74ZmJVcKVhyUwWg=" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-05:00" level=debug msg="completed challenge" Jan 10 23:41:21 music go-librespot[32506]: time="2026-01-10T23:41:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=debug msg="completed challenge" Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:22 music volumio[32224]: info: Initializing connection to go-librespot Websocket Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=debug msg="new websocket client" Jan 10 23:41:22 music volumio[32224]: info: Connection to go-librespot Websocket established Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=debug msg="completed challenge" Jan 10 23:41:22 music go-librespot[32506]: time="2026-01-10T23:41:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 10 23:41:23 music volumio[32224]: info: Adding plugin bluetooth to MyMusic Plugins Jan 10 23:41:23 music volumio[32224]: info: Adding plugin multiroom to MyMusic Plugins Jan 10 23:41:23 music volumio[32224]: info: Adding plugin metavolumio to MyMusic Plugins Jan 10 23:41:23 music volumio[32224]: info: Adding plugin cd_controller to MyMusic Plugins Jan 10 23:41:23 music volumio[32224]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 10 23:41:23 music volumio[32224]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 10 23:41:23 music volumio[32224]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 10 23:41:23 music volumio[32224]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 10 23:41:23 music go-librespot[32506]: time="2026-01-10T23:41:23-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:41:23 music go-librespot[32506]: time="2026-01-10T23:41:23-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:23 music go-librespot[32506]: time="2026-01-10T23:41:23-05:00" level=debug msg="completed challenge" Jan 10 23:41:23 music go-librespot[32506]: time="2026-01-10T23:41:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:24 music go-librespot[32506]: time="2026-01-10T23:41:24-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:41:24 music go-librespot[32506]: time="2026-01-10T23:41:24-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:24 music go-librespot[32506]: time="2026-01-10T23:41:24-05:00" level=debug msg="completed challenge" Jan 10 23:41:24 music volumio[32224]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 10 23:41:24 music volumio[32224]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 10 23:41:24 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:24 music volumio[32224]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:24 music volumio[32224]: info: Starting MyVolumio Remote Streaming Endpoints Jan 10 23:41:24 music volumio[32224]: info: MyVolumio login type: Token Jan 10 23:41:24 music volumio[32224]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 10 23:41:24 music volumio[32224]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 10 23:41:24 music go-librespot[32506]: time="2026-01-10T23:41:24-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:25 music go-librespot[32506]: time="2026-01-10T23:41:25-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 10 23:41:25 music go-librespot[32506]: time="2026-01-10T23:41:25-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:25 music go-librespot[32506]: time="2026-01-10T23:41:25-05:00" level=debug msg="completed challenge" Jan 10 23:41:25 music volumio[32224]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 10 23:41:25 music volumio[32224]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 10 23:41:25 music volumio[32224]: info: Streaming services startup Jan 10 23:41:25 music volumio[32224]: info: Starting Streaming Daemon Jan 10 23:41:25 music sudo[32516]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 10 23:41:25 music sudo[32516]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:25 music volumio[32224]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 10 23:41:25 music sudo[32516]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:25 music go-librespot[32506]: time="2026-01-10T23:41:25-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:25 music go-librespot[32506]: time="2026-01-10T23:41: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 " Jan 10 23:41:25 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:25 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:41:25 music volumio[32224]: info: Getting Spotify volume Jan 10 23:41:25 music volumio[32224]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:41:25 music volumio[32224]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 23:41:25 music volumio[32224]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 10 23:41:25 music volumio[32224]: errno: -111, Jan 10 23:41:25 music volumio[32224]: code: 'ECONNREFUSED', Jan 10 23:41:25 music volumio[32224]: syscall: 'connect', Jan 10 23:41:25 music volumio[32224]: address: '127.0.0.1', Jan 10 23:41:25 music volumio[32224]: port: 9879, Jan 10 23:41:25 music volumio[32224]: response: undefined Jan 10 23:41:25 music volumio[32224]: } Jan 10 23:41:25 music volumio[32224]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:41:26 music sudo[32551]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 23:40' Jan 10 23:41:26 music sudo[32551]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:26 music sudo[32551]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:26 music volumio-remote-updater[22000]: [2026-01-10 23:41:26] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 23:41:26 music volumio-remote-updater[22000]: [2026-01-10 23:41:26] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 23:41:26 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:26 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 23:41:26 music systemd[1]: volumio.service: Consumed 26.454s CPU time. Jan 10 23:41:26 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:41:26 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:41:27 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4336. Jan 10 23:41:27 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:41:27 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 23:41:27 music systemd[1]: volumio.service: Consumed 26.454s CPU time. Jan 10 23:41:27 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 23:41:27 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:41:28 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 10 23:41:28 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:28 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:28 music go-librespot[32578]: go-librespot daemon starting... Jan 10 23:41:28 music go-librespot[32579]: time="2026-01-10T23:41:28-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:28 music go-librespot[32579]: time="2026-01-10T23:41:28-05:00" level=debug msg="app state loaded" Jan 10 23:41:28 music go-librespot[32579]: time="2026-01-10T23:41:28-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:29 music volumio[32563]: info: ------------------------------------------- Jan 10 23:41:29 music volumio[32563]: info: ----- Volumio3 ---- Jan 10 23:41:29 music volumio[32563]: info: ------------------------------------------- Jan 10 23:41:29 music volumio[32563]: info: ----- System startup ---- Jan 10 23:41:29 music volumio[32563]: info: ------------------------------------------- Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41: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]" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41: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]" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41: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]" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41:29-05:00" level=info msg="zeroconf server listening on port 45223" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41:29-05:00" level=debug msg="obtained new client token: AADdMNLQy70umEhPBYph5OmvJrRaUApS9E1IfUOgiaUeBEFwY3+53JDXbAPoraM3FgQBA9Y0pfuYIfajX6g17tjr6MgrEb+Y3NJBH/zzTl183WTiziQX85/4fIkzkfjW+zHS3yx3e62w+2lTpt98uLpLO079hRZyl3BAhjH5AJ/t4IJzGYD6sp+Y0OVRwYT8Xl/pjmf8tzV/i5/kzkkQOLakjaIYhjCXNw5MnERHl1KCuHTNJOK12eI=" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41:29-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41:29-05:00" level=debug msg="completed challenge" Jan 10 23:41:29 music go-librespot[32579]: time="2026-01-10T23:41:29-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:29 music volumio[32563]: info: MYVOLUMIO Environment detected Jan 10 23:41:29 music volumio[32563]: info: Plugin folders cleanup Jan 10 23:41:29 music volumio[32563]: info: Scanning into folder /volumio/app/plugins/ Jan 10 23:41:29 music volumio[32563]: info: Scanning category audio_interface Jan 10 23:41:29 music volumio[32563]: info: Scanning category miscellanea Jan 10 23:41:30 music volumio[32563]: info: Scanning category music_service Jan 10 23:41:30 music volumio[32563]: info: Scanning category plugins.json Jan 10 23:41:30 music volumio[32563]: info: Scanning category system_controller Jan 10 23:41:30 music volumio[32563]: info: Scanning category user_interface Jan 10 23:41:30 music volumio[32563]: info: Scanning into folder /data/plugins/ Jan 10 23:41:30 music volumio[32563]: info: Scanning category music_service Jan 10 23:41:30 music volumio[32563]: info: Plugin folders cleanup completed Jan 10 23:41:30 music volumio[32563]: info: ------------------------------------------- Jan 10 23:41:30 music volumio[32563]: info: ----- Core plugins startup ---- Jan 10 23:41:30 music volumio[32563]: info: ------------------------------------------- Jan 10 23:41:30 music volumio[32563]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 23:41:30 music volumio[32563]: info: Adding plugin upnp to MyMusic Plugins Jan 10 23:41:30 music volumio[32563]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 23:41:30 music volumio[32563]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 23:41:30 music volumio[32563]: info: Loading plugins from folder /data/plugins/ Jan 10 23:41:30 music volumio[32563]: info: Loading plugin "system"... Jan 10 23:41:30 music volumio[32563]: info: Loading plugin "appearance"... Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=debug msg="completed challenge" Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=debug msg="completed challenge" Jan 10 23:41:30 music go-librespot[32579]: time="2026-01-10T23:41:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "network"... Jan 10 23:41:31 music volumio[32563]: info: Refreshing Cached IP Addresses Jan 10 23:41:31 music sudo[32601]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:41:31 music sudo[32601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:31 music sudo[32601]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:31 music sudo[32603]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:41:31 music sudo[32603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:31 music sudo[32603]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "services"... Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "alsa_controller"... Jan 10 23:41:31 music sudo[32611]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 23:41:31 music sudo[32611]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:31 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "wizard"... Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "networkfs"... Jan 10 23:41:31 music volumio[32563]: info: Starting Udev Watcher for removable devices Jan 10 23:41:31 music volumio[32563]: info: Ignoring mount for partition: boot Jan 10 23:41:31 music volumio[32563]: info: Ignoring mount for partition: volumio Jan 10 23:41:31 music volumio[32563]: info: Ignoring mount for partition: volumio_data Jan 10 23:41:31 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "volumio_command_line_client"... Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "upnp"... Jan 10 23:41:31 music volumio[32563]: info: [1768106491392] Starting Upmpd Daemon Jan 10 23:41:31 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "my_music"... Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "mpd"... Jan 10 23:41:31 music go-librespot[32579]: time="2026-01-10T23:41:31-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:41:31 music go-librespot[32579]: time="2026-01-10T23:41:31-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:31 music go-librespot[32579]: time="2026-01-10T23:41:31-05:00" level=debug msg="completed challenge" Jan 10 23:41:31 music go-librespot[32579]: time="2026-01-10T23:41:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:31 music volumio-remote-updater[22000]: [2026-01-10 23:41:31] [connect] Successful connection Jan 10 23:41:31 music volumio[32563]: info: Loading plugin "upnp_browser"... Jan 10 23:41:31 music sudo[32611]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:32 music go-librespot[32579]: time="2026-01-10T23:41:32-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:41:32 music go-librespot[32579]: time="2026-01-10T23:41:32-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:32 music go-librespot[32579]: time="2026-01-10T23:41:32-05:00" level=debug msg="completed challenge" Jan 10 23:41:32 music go-librespot[32579]: time="2026-01-10T23:41:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:33 music volumio[32563]: info: Starting UPNP Browser Jan 10 23:41:33 music volumio[32563]: info: Loading plugin "alarm-clock"... Jan 10 23:41:33 music go-librespot[32579]: time="2026-01-10T23:41:33-05:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:80, retrying with a different AP" error="dial tcp 104.199.65.9:80: connect: connection refused" Jan 10 23:41:33 music go-librespot[32579]: time="2026-01-10T23:41:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:33 music volumio[32563]: info: Loading plugin "airplay_emulation"... Jan 10 23:41:33 music volumio[32563]: info: Starting Shairport Sync Jan 10 23:41:33 music volumio[32563]: info: Loading plugin "last_100"... Jan 10 23:41:33 music volumio[32563]: info: Loading plugin "webradio"... Jan 10 23:41:33 music go-librespot[32579]: time="2026-01-10T23:41:33-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:33 music go-librespot[32579]: time="2026-01-10T23:41:33-05:00" level=debug msg="completed challenge" Jan 10 23:41:33 music go-librespot[32579]: time="2026-01-10T23:41:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:33 music go-librespot[32579]: time="2026-01-10T23:41: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 " Jan 10 23:41:33 music volumio[32563]: info: Loading plugin "i2s_dacs"... Jan 10 23:41:33 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:33 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:41:33 music volumio[32563]: info: I2S DAC not set, start Auto-detection Jan 10 23:41:33 music volumio[32563]: info: Loading plugin "volumiodiscovery"... Jan 10 23:41:33 music volumio[32563]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:33 music volumio[32563]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:33 music volumio[32563]: *** WARNING *** For more information see Jan 10 23:41:33 music volumio[32563]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:33 music volumio[32563]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:33 music volumio[32563]: *** WARNING *** For more information see Jan 10 23:41:33 music node[32563]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:33 music node[32563]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:33 music node[32563]: *** WARNING *** For more information see Jan 10 23:41:33 music node[32563]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:33 music node[32563]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:33 music node[32563]: *** WARNING *** For more information see Jan 10 23:41:33 music volumio[32563]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 23:41:33 music volumio[32563]: info: Discovery: Started advertising with name: music Jan 10 23:41:33 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:33 music volumio[32563]: info: Loading plugin "spop"... Jan 10 23:41:34 music volumio[32563]: info: Loading plugin "outputs"... Jan 10 23:41:34 music volumio[32563]: info: Loading plugin "albumart"... Jan 10 23:41:34 music volumio[32563]: info: Plugin example_plugin is not enabled Jan 10 23:41:34 music volumio[32563]: info: Loading plugin "inputs"... Jan 10 23:41:34 music volumio[32563]: info: Loading plugin "updater_comm"... Jan 10 23:41:34 music volumio[32563]: info: Plugin mpdemulation is not enabled Jan 10 23:41:34 music volumio[32563]: info: Loading plugin "rest_api"... Jan 10 23:41:34 music volumio[32563]: info: Loading plugin "websocket"... Jan 10 23:41:34 music volumio[32563]: info: Starting Socket.io Server version 1.7.4 Jan 10 23:41:35 music volumio[32563]: info: Loading i18n strings for locale en Jan 10 23:41:35 music volumio[32563]: Updating browse sources language Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::initPlayerControls Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:35 music volumio[32563]: Express server listening on port 3000 Jan 10 23:41:35 music volumio[32563]: [Metrics] WebUI: 6s 632.06ms Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::resetVolumioState Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::getcurrentVolume Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: Volumio Network Manager: Network status updated: 1 Jan 10 23:41:35 music volumio[32636]: Forking 3 albumart workers Jan 10 23:41:35 music volumio[32563]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::pushState Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::updateTrackBlock Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrackBlock Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:35 music volumio-remote-updater[22000]: [2026-01-10 23:41:35] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768106491 101 Jan 10 23:41:35 music volumio[32563]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 10 23:41:35 music volumio[32563]: info: Reloading queue from file Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::setRepeat null single undefined Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::pushState Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::setRandom null Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::pushState Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:35 music volumio[32563]: info: Setting Device type: Raspberry PI Jan 10 23:41:35 music volumio[32563]: info: Listing playlists Jan 10 23:41:35 music volumio[32563]: info: Listing playlists Jan 10 23:41:35 music volumio[32563]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:41:35 music volumio[32563]: info: CoreStateMachine::pushState Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:35 music volumio[32563]: info: Completed loading Core Plugins Jan 10 23:41:35 music volumio[32563]: info: Preparing to generate the ALSA configuration file Jan 10 23:41:35 music volumio[32563]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:41:35 music volumio[32563]: info: Discovery: Found device music Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:35 music volumio[32563]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:41:35 music volumio[32563]: info: Discovery: Found device music Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:35 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:35 music volumio[32563]: info: Asound.conf file unchanged, so no further update is needed Jan 10 23:41:35 music volumio[32563]: info: Output device has changed, restarting MPD Jan 10 23:41:35 music volumio[32563]: info: Output device has changed, restarting Shairport Sync Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:35 music sudo[32691]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:41:35 music sudo[32691]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:35 music sudo[32691]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:35 music sudo[32692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:41:35 music sudo[32692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:35 music volumio[32563]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:35 music volumio[32563]: info: ___________ START PLUGINS ___________ Jan 10 23:41:35 music volumio[32563]: info: ControllerMpd::onStart: Initializing MPD Jan 10 23:41:35 music volumio[32563]: info: Creating MPD Configuration file Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:35 music volumio[32563]: info: [1768106495936] CoreMusicLibrary::Adding element Media Servers Jan 10 23:41:35 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:35 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 23:41:35 music sudo[32701]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:41:35 music sudo[32701]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:35 music volumio[32563]: info: UPNP Browser: Client initialized successfully Jan 10 23:41:35 music sudo[32702]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:41:36 music sudo[32702]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:36 music sudo[32701]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:36 music systemd[1]: mpd.service: Deactivated successfully. Jan 10 23:41:36 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 23:41:36 music systemd[1]: mpd.service: Consumed 4.072s CPU time. Jan 10 23:41:36 music systemd[1]: mpd.socket: Deactivated successfully. Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:36 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 23:41:36 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 23:41:36 music volumio[32563]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:36 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 23:41:36 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 23:41:36 music systemd[1]: mpd.service: Deactivated successfully. Jan 10 23:41:36 music volumio[32563]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:36 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 23:41:36 music systemd[1]: mpd.socket: Deactivated successfully. Jan 10 23:41:36 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 23:41:36 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:36 music volumio[32563]: info: [1768106496131] CoreMusicLibrary::Adding element Last_100 Jan 10 23:41:36 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:36 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:36 music volumio[32563]: info: [1768106496160] CoreMusicLibrary::Adding element Webradio Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:36 music volumio[32563]: info: Initializing BBC Radios Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:36 music volumio[32563]: info: Creating Spotify config file Jan 10 23:41:36 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:36 music sudo[32716]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 23:41:36 music sudo[32716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 23:41:36 music sudo[32716]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:36 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 10 23:41:36 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:36 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:36 music go-librespot[32732]: go-librespot daemon starting... Jan 10 23:41:36 music volumio[32563]: info: Volumio Calling Home Jan 10 23:41:36 music go-librespot[32733]: time="2026-01-10T23:41:36-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:37 music volumio[32653]: Starting albumart workers Jan 10 23:41:37 music go-librespot[32733]: time="2026-01-10T23:41:37-05:00" level=info msg="zeroconf server listening on port 41805" Jan 10 23:41:37 music volumio[32654]: Starting albumart workers Jan 10 23:41:37 music volumio[32563]: info: MPD Permissions set Jan 10 23:41:37 music volumio[32563]: info: MPD Permissions set Jan 10 23:41:37 music volumio[32651]: Starting albumart workers Jan 10 23:41:37 music volumio[32563]: info: Volumio called home Jan 10 23:41:37 music volumio[32563]: info: Spotify config file written Jan 10 23:41:37 music volumio[32563]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music sudo[32746]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:41:37 music sudo[32746]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:37 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:38 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:41:38 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:41:38 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:38 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:38 music volumio[32563]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:38 music volumio[32563]: info: No need to fix Spotify hosts Jan 10 23:41:38 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:38 music go-librespot[32758]: go-librespot daemon starting... Jan 10 23:41:38 music sudo[32746]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41:38-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41:38-05:00" level=debug msg="app state loaded" Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41:38-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41: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-gew4.spotify.com:80]" Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41:38-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]" Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41:38-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]" Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41:38-05:00" level=info msg="zeroconf server listening on port 40341" Jan 10 23:41:38 music go-librespot[32759]: time="2026-01-10T23:41:38-05:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp [2600:1901:1:7c5::]:443: connect: cannot assign requested address" Jan 10 23:41:38 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:38 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:41:38 music volumio[32563]: info: Starting Shairport Sync Jan 10 23:41:38 music volumio[32563]: info: Starting Shairport Sync Jan 10 23:41:38 music volumio[32563]: info: Starting Shairport Sync Jan 10 23:41:38 music sudo[317]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:41:38 music sudo[317]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:38 music sudo[319]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:41:38 music sudo[319]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:38 music volumio[32563]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 10 23:41:38 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 23:41:38 music sudo[322]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:41:38 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 23:41:38 music sudo[322]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:38 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:38 music systemd[1]: shairport-sync.service: Consumed 1.860s CPU time. Jan 10 23:41:38 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:39 music sudo[317]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:39 music volumio[32563]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:39 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:39 music volumio[32563]: info: Shairport-Sync Started Jan 10 23:41:39 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 23:41:39 music volumio[32563]: Error adding Membership: Error: addMembership EINVAL Jan 10 23:41:39 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 23:41:39 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:39 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:41:39 music sudo[322]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:39 music sudo[319]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:39 music volumio[32563]: info: Shairport-Sync Started Jan 10 23:41:39 music volumio[32563]: info: Shairport-Sync Started Jan 10 23:41:39 music volumio[32563]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:39 music volumio[32563]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:40 music mpd[32731]: 2026-01-10T23:41:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 23:41:40 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 23:41:40 music sudo[32702]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:40 music sudo[32692]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:40 music volumio[32563]: info: Completed starting Core Plugins Jan 10 23:41:40 music volumio[32563]: info: ------------------------------------------- Jan 10 23:41:40 music volumio[32563]: info: ----- MyVolumio plugins startup ---- Jan 10 23:41:40 music volumio[32563]: info: ------------------------------------------- Jan 10 23:41:40 music volumio[32563]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 10 23:41:40 music volumio[32563]: error: MPD error: The expression evaluated to a falsy value: Jan 10 23:41:40 music volumio[32563]: assert.ok(self.idling) Jan 10 23:41:40 music volumio[32563]: error: The expression evaluated to a falsy value: Jan 10 23:41:40 music volumio[32563]: assert.ok(self.idling) Jan 10 23:41:40 music volumio[32563]: info: MPD running with PID32731 Jan 10 23:41:40 music volumio[32563]: ,establishing connection Jan 10 23:41:40 music volumio[32563]: error: updateQueue error: null Jan 10 23:41:40 music volumio[32563]: error: updateQueue error: null Jan 10 23:41:41 music sudo[370]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:41:41 music sudo[370]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:41 music sudo[372]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:41:41 music sudo[372]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:41 music sudo[370]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:41 music sudo[372]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:41 music sudo[376]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 23:41:41 music sudo[376]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:41 music sudo[376]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:41 music volumio[32563]: info: Upmpdcli Daemon Started Jan 10 23:41:41 music volumio[32563]: info: go-librespot daemon successfully initialized Jan 10 23:41:41 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 10 23:41:41 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:41 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:41 music go-librespot[378]: go-librespot daemon starting... Jan 10 23:41:41 music go-librespot[379]: time="2026-01-10T23:41:41-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:41 music go-librespot[379]: time="2026-01-10T23:41:41-05:00" level=debug msg="app state loaded" Jan 10 23:41:41 music go-librespot[379]: time="2026-01-10T23:41:41-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-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]" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-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]" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-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]" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-05:00" level=info msg="zeroconf server listening on port 41827" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-05:00" level=debug msg="obtained new client token: AAB8uPgWfN5unzYSxsiYrv/+2Gz70UjkKVFBuA99ZM7Ws/aCOzy6ZYFRpkpIRgG4v8PXxxjK4YmnwMhsH9aRGRqGwRXrt+eSUDjxHTMDY1NztCVh34iAEf5AhWZoFq3MGt9CiRpn7nEciOngJLV0LXjBbL8jKz+kePZmN/D7f8Un/WRCajGmFIjsNLKshyXNdDKcCXAG39C03c8W9T//NNtvVkXk5UoVvSGVvwqFKz8cgTgjT9R7ZPM=" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-05:00" level=debug msg="completed challenge" Jan 10 23:41:42 music go-librespot[379]: time="2026-01-10T23:41:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:43 music go-librespot[379]: time="2026-01-10T23:41:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:43 music go-librespot[379]: time="2026-01-10T23:41:43-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:43 music go-librespot[379]: time="2026-01-10T23:41:43-05:00" level=debug msg="completed challenge" Jan 10 23:41:43 music go-librespot[379]: time="2026-01-10T23:41:43-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:43 music sudo[392]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:41:43 music sudo[392]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:43 music sudo[395]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:41:43 music sudo[395]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:43 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 23:41:43 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 23:41:43 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 23:41:43 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 23:41:43 music mpd_monitor.sh[397]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 23:41:43 music sudo[392]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:43 music volumio[32563]: info: Successfully started MPD Monitor Jan 10 23:41:43 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 23:41:43 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 23:41:43 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 23:41:43 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 23:41:43 music sudo[395]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:43 music mpd_monitor.sh[401]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 23:41:43 music volumio[32563]: info: Successfully started MPD Monitor Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=debug msg="completed challenge" Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=debug msg="completed challenge" Jan 10 23:41:44 music volumio[32563]: info: Initializing connection to go-librespot Websocket Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=debug msg="new websocket client" Jan 10 23:41:44 music volumio[32563]: info: Connection to go-librespot Websocket established Jan 10 23:41:44 music go-librespot[379]: time="2026-01-10T23:41:44-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:45 music go-librespot[379]: time="2026-01-10T23:41:45-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:41:45 music volumio[32563]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 10 23:41:45 music go-librespot[379]: time="2026-01-10T23:41:45-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:45 music go-librespot[379]: time="2026-01-10T23:41:45-05:00" level=debug msg="completed challenge" Jan 10 23:41:45 music go-librespot[379]: time="2026-01-10T23:41:45-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:46 music go-librespot[379]: time="2026-01-10T23:41:46-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 10 23:41:46 music go-librespot[379]: time="2026-01-10T23:41:46-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:46 music go-librespot[379]: time="2026-01-10T23:41:46-05:00" level=debug msg="completed challenge" Jan 10 23:41:46 music go-librespot[379]: time="2026-01-10T23:41:46-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:46 music go-librespot[379]: time="2026-01-10T23:41:46-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 " Jan 10 23:41:46 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:46 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:41:46 music volumio[32563]: info: Connection to go-librespot Websocket closed Jan 10 23:41:47 music volumio[32563]: info: Getting Spotify volume Jan 10 23:41:47 music volumio[32563]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:41:47 music volumio[32563]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 23:41:47 music volumio[32563]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 10 23:41:47 music volumio[32563]: errno: -111, Jan 10 23:41:47 music volumio[32563]: code: 'ECONNREFUSED', Jan 10 23:41:47 music volumio[32563]: syscall: 'connect', Jan 10 23:41:47 music volumio[32563]: address: '127.0.0.1', Jan 10 23:41:47 music volumio[32563]: port: 9879, Jan 10 23:41:47 music volumio[32563]: response: undefined Jan 10 23:41:47 music volumio[32563]: } Jan 10 23:41:47 music volumio[32563]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:41:48 music sudo[419]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 23:40' Jan 10 23:41:48 music sudo[419]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:48 music sudo[419]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:48 music volumio-remote-updater[22000]: [2026-01-10 23:41:48] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 23:41:48 music volumio-remote-updater[22000]: [2026-01-10 23:41:48] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 23:41:48 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:48 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 23:41:48 music systemd[1]: volumio.service: Consumed 23.438s CPU time. Jan 10 23:41:49 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:41:49 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:41:49 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4337. Jan 10 23:41:49 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:41:49 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 23:41:49 music systemd[1]: volumio.service: Consumed 23.438s CPU time. Jan 10 23:41:49 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 23:41:49 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:41:50 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 10 23:41:50 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:50 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:50 music go-librespot[454]: go-librespot daemon starting... Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=debug msg="app state loaded" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-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]" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-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]" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-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]" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=info msg="zeroconf server listening on port 36231" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=debug msg="obtained new client token: AAC68okbx5qNq1qORq/L+oCibyfsemR81auhX9UrXJbjz9x7UxDVF25kMC7AzTA8RzdMrphuu1v+5xSOa7MbXP9ij3A9vnay7Xbmc+oNQoMs2oqQru4EQFFmoV1rYNekx/tluVwLDp5v0omECuj0Qx6eBby7AX/O2LkfnnbAnfjKqMBr8F1XDqr9HbE7/TiFW2QxC9ikcSaPzUwVQtnsOP67aoGkc8EkQR5Yr2sZYu56p4ARlfgsLbI=" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=debug msg="completed challenge" Jan 10 23:41:50 music go-librespot[455]: time="2026-01-10T23:41:50-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:51 music volumio[438]: info: ------------------------------------------- Jan 10 23:41:51 music volumio[438]: info: ----- Volumio3 ---- Jan 10 23:41:51 music volumio[438]: info: ------------------------------------------- Jan 10 23:41:51 music volumio[438]: info: ----- System startup ---- Jan 10 23:41:51 music volumio[438]: info: ------------------------------------------- Jan 10 23:41:51 music go-librespot[455]: time="2026-01-10T23:41:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:51 music go-librespot[455]: time="2026-01-10T23:41:51-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:51 music go-librespot[455]: time="2026-01-10T23:41:51-05:00" level=debug msg="completed challenge" Jan 10 23:41:51 music go-librespot[455]: time="2026-01-10T23:41:51-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:52 music volumio[438]: info: MYVOLUMIO Environment detected Jan 10 23:41:52 music go-librespot[455]: time="2026-01-10T23:41:52-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:41:52 music volumio[438]: info: Plugin folders cleanup Jan 10 23:41:52 music volumio[438]: info: Scanning into folder /volumio/app/plugins/ Jan 10 23:41:52 music volumio[438]: info: Scanning category audio_interface Jan 10 23:41:52 music volumio[438]: info: Scanning category miscellanea Jan 10 23:41:52 music volumio[438]: info: Scanning category music_service Jan 10 23:41:52 music volumio[438]: info: Scanning category plugins.json Jan 10 23:41:52 music volumio[438]: info: Scanning category system_controller Jan 10 23:41:52 music volumio[438]: info: Scanning category user_interface Jan 10 23:41:52 music volumio[438]: info: Scanning into folder /data/plugins/ Jan 10 23:41:52 music volumio[438]: info: Scanning category music_service Jan 10 23:41:52 music volumio[438]: info: Plugin folders cleanup completed Jan 10 23:41:52 music volumio[438]: info: ------------------------------------------- Jan 10 23:41:52 music volumio[438]: info: ----- Core plugins startup ---- Jan 10 23:41:52 music volumio[438]: info: ------------------------------------------- Jan 10 23:41:52 music volumio[438]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 23:41:52 music volumio[438]: info: Adding plugin upnp to MyMusic Plugins Jan 10 23:41:52 music volumio[438]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 23:41:52 music volumio[438]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 23:41:52 music volumio[438]: info: Loading plugins from folder /data/plugins/ Jan 10 23:41:52 music volumio[438]: info: Loading plugin "system"... Jan 10 23:41:52 music volumio[438]: info: Loading plugin "appearance"... Jan 10 23:41:52 music go-librespot[455]: time="2026-01-10T23:41:52-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:52 music go-librespot[455]: time="2026-01-10T23:41:52-05:00" level=debug msg="completed challenge" Jan 10 23:41:52 music go-librespot[455]: time="2026-01-10T23:41:52-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:52 music go-librespot[455]: time="2026-01-10T23:41:52-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:41:53 music go-librespot[455]: time="2026-01-10T23:41:53-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:53 music go-librespot[455]: time="2026-01-10T23:41:53-05:00" level=debug msg="completed challenge" Jan 10 23:41:53 music go-librespot[455]: time="2026-01-10T23:41:53-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:53 music volumio[438]: info: Loading plugin "network"... Jan 10 23:41:53 music volumio[438]: info: Refreshing Cached IP Addresses Jan 10 23:41:53 music sudo[477]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:41:53 music sudo[477]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:53 music sudo[480]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:41:53 music sudo[480]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:53 music sudo[477]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:53 music volumio[438]: info: Loading plugin "services"... Jan 10 23:41:53 music sudo[480]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:53 music volumio[438]: info: Loading plugin "alsa_controller"... Jan 10 23:41:53 music sudo[498]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 23:41:53 music sudo[498]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:53 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:53 music volumio[438]: info: Loading plugin "wizard"... Jan 10 23:41:53 music volumio[438]: info: Loading plugin "networkfs"... Jan 10 23:41:53 music volumio[438]: info: Starting Udev Watcher for removable devices Jan 10 23:41:53 music volumio[438]: info: Ignoring mount for partition: boot Jan 10 23:41:53 music volumio[438]: info: Ignoring mount for partition: volumio Jan 10 23:41:53 music volumio[438]: info: Ignoring mount for partition: volumio_data Jan 10 23:41:53 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:53 music volumio[438]: info: Loading plugin "volumio_command_line_client"... Jan 10 23:41:53 music volumio[438]: info: Loading plugin "upnp"... Jan 10 23:41:53 music volumio[438]: info: [1768106513592] Starting Upmpd Daemon Jan 10 23:41:53 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:53 music volumio[438]: info: Loading plugin "my_music"... Jan 10 23:41:53 music volumio[438]: info: Loading plugin "mpd"... Jan 10 23:41:53 music go-librespot[455]: time="2026-01-10T23:41:53-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:41:53 music volumio-remote-updater[22000]: [2026-01-10 23:41:53] [connect] Successful connection Jan 10 23:41:53 music go-librespot[455]: time="2026-01-10T23:41:53-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:53 music go-librespot[455]: time="2026-01-10T23:41:53-05:00" level=debug msg="completed challenge" Jan 10 23:41:53 music volumio[438]: info: Loading plugin "upnp_browser"... Jan 10 23:41:54 music sudo[498]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:54 music go-librespot[455]: time="2026-01-10T23:41:54-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:54 music go-librespot[455]: time="2026-01-10T23:41:54-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 10 23:41:54 music go-librespot[455]: time="2026-01-10T23:41:54-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:54 music go-librespot[455]: time="2026-01-10T23:41:54-05:00" level=debug msg="completed challenge" Jan 10 23:41:55 music go-librespot[455]: time="2026-01-10T23:41:55-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:55 music go-librespot[455]: time="2026-01-10T23:41:55-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 " Jan 10 23:41:55 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:41:55 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:41:55 music volumio[438]: info: Starting UPNP Browser Jan 10 23:41:55 music volumio[438]: info: Loading plugin "alarm-clock"... Jan 10 23:41:55 music volumio[438]: info: Loading plugin "airplay_emulation"... Jan 10 23:41:55 music volumio[438]: info: Starting Shairport Sync Jan 10 23:41:55 music volumio[438]: info: Loading plugin "last_100"... Jan 10 23:41:55 music volumio[438]: info: Loading plugin "webradio"... Jan 10 23:41:55 music volumio[438]: info: Loading plugin "i2s_dacs"... Jan 10 23:41:55 music volumio[438]: info: I2S DAC not set, start Auto-detection Jan 10 23:41:55 music volumio[438]: info: Loading plugin "volumiodiscovery"... Jan 10 23:41:55 music volumio[438]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:55 music volumio[438]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:55 music volumio[438]: *** WARNING *** For more information see Jan 10 23:41:55 music volumio[438]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:55 music volumio[438]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:55 music volumio[438]: *** WARNING *** For more information see Jan 10 23:41:55 music node[438]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:55 music node[438]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:55 music node[438]: *** WARNING *** For more information see Jan 10 23:41:55 music node[438]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:41:55 music node[438]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:41:55 music node[438]: *** WARNING *** For more information see Jan 10 23:41:55 music volumio[438]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 23:41:55 music volumio[438]: info: Discovery: Started advertising with name: music Jan 10 23:41:55 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:41:55 music volumio[438]: info: Loading plugin "spop"... Jan 10 23:41:56 music volumio[438]: info: Loading plugin "outputs"... Jan 10 23:41:56 music volumio[438]: info: Loading plugin "albumart"... Jan 10 23:41:57 music volumio[438]: info: Plugin example_plugin is not enabled Jan 10 23:41:57 music volumio[438]: info: Loading plugin "inputs"... Jan 10 23:41:57 music volumio[438]: info: Loading plugin "updater_comm"... Jan 10 23:41:57 music volumio[438]: info: Plugin mpdemulation is not enabled Jan 10 23:41:57 music volumio[438]: info: Loading plugin "rest_api"... Jan 10 23:41:57 music volumio[438]: info: Loading plugin "websocket"... Jan 10 23:41:57 music volumio[438]: info: Starting Socket.io Server version 1.7.4 Jan 10 23:41:57 music volumio[438]: info: Loading i18n strings for locale en Jan 10 23:41:57 music volumio[438]: Updating browse sources language Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::initPlayerControls Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:57 music volumio[438]: Express server listening on port 3000 Jan 10 23:41:57 music volumio[438]: [Metrics] WebUI: 6s 571.01ms Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::resetVolumioState Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::getcurrentVolume Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:57 music volumio[438]: info: Volumio Network Manager: Network status updated: 1 Jan 10 23:41:57 music volumio[520]: Forking 3 albumart workers Jan 10 23:41:57 music volumio-remote-updater[22000]: [2026-01-10 23:41:57] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768106513 101 Jan 10 23:41:57 music volumio[438]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 10 23:41:57 music volumio[438]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::pushState Jan 10 23:41:57 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::updateTrackBlock Jan 10 23:41:57 music volumio[438]: info: CorePlayQueue::getTrackBlock Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:41:57 music volumio[438]: info: Reloading queue from file Jan 10 23:41:57 music volumio[438]: info: Setting Device type: Raspberry PI Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::setRepeat null single undefined Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::pushState Jan 10 23:41:57 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::setRandom null Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::pushState Jan 10 23:41:57 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:57 music volumio[438]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:41:57 music volumio[438]: info: CoreStateMachine::pushState Jan 10 23:41:57 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioPushState Jan 10 23:41:57 music volumio[438]: info: Completed loading Core Plugins Jan 10 23:41:57 music volumio[438]: info: Preparing to generate the ALSA configuration file Jan 10 23:41:57 music volumio[438]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:41:57 music volumio[438]: info: Discovery: Found device music Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:57 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:57 music volumio[438]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:41:57 music volumio[438]: info: Discovery: Found device music Jan 10 23:41:57 music volumio[438]: info: CoreCommandRouter::volumioGetState Jan 10 23:41:57 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:41:57 music volumio[438]: info: Asound.conf file unchanged, so no further update is needed Jan 10 23:41:57 music volumio[438]: info: Output device has changed, restarting MPD Jan 10 23:41:58 music volumio[438]: info: Output device has changed, restarting Shairport Sync Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:58 music sudo[575]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:41:58 music sudo[575]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:58 music sudo[575]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:58 music sudo[577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:41:58 music volumio[438]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:58 music sudo[577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:58 music volumio[438]: info: ___________ START PLUGINS ___________ Jan 10 23:41:58 music volumio[438]: info: ControllerMpd::onStart: Initializing MPD Jan 10 23:41:58 music volumio[438]: info: Creating MPD Configuration file Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:58 music volumio[438]: info: [1768106518150] CoreMusicLibrary::Adding element Media Servers Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:58 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 10 23:41:58 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:58 music sudo[586]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:41:58 music volumio[438]: info: UPNP Browser: Client initialized successfully Jan 10 23:41:58 music sudo[586]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:58 music sudo[588]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:41:58 music sudo[588]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:41:58 music sudo[586]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:58 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:41:58 music go-librespot[589]: go-librespot daemon starting... Jan 10 23:41:58 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-05:00" level=debug msg="app state loaded" Jan 10 23:41:58 music volumio[438]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:41:58 music volumio[438]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:58 music volumio[438]: info: [1768106518356] CoreMusicLibrary::Adding element Last_100 Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:41:58 music volumio[438]: info: [1768106518367] CoreMusicLibrary::Adding element Webradio Jan 10 23:41:58 music systemd[1]: mpd.service: Deactivated successfully. Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:41:58 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 23:41:58 music systemd[1]: mpd.service: Consumed 4.129s CPU time. Jan 10 23:41:58 music systemd[1]: mpd.socket: Deactivated successfully. Jan 10 23:41:58 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 23:41:58 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:58 music volumio[438]: info: Initializing BBC Radios Jan 10 23:41:58 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 23:41:58 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:41:58 music volumio[438]: info: Creating Spotify config file Jan 10 23:41:58 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:41:58 music sudo[624]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 23:41:58 music sudo[624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-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]" Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-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]" Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-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]" Jan 10 23:41:58 music sudo[624]: pam_unix(sudo:session): session closed for user root Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-05:00" level=info msg="zeroconf server listening on port 43049" Jan 10 23:41:58 music go-librespot[595]: time="2026-01-10T23:41:58-05:00" level=debug msg="obtained new client token: AACrPpzNw9YfLhkOxcb4AAzczrNzJ7JVz9tMY2fH/DWN3oBcmqIXDj+9/z9Vvqmq3DzbR33L+aHQ47ZsOTnR0uG7Bo+7rPsDlIRNv80cRF3TU85BA26aksLMcZ5aLGX72M8tQBiLQptA0xYvRPmRD806eMN9agupY/m71NMUvUYtcBHXwDPBXKY/fDAyZbAfAtdN7sNXI7NLf9e9BwPVO21hhCqB+qusHESD2LduAGOlnUR/PfuDN5c=" Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=debug msg="completed challenge" Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:59 music volumio[438]: info: Volumio Calling Home Jan 10 23:41:59 music volumio[537]: Starting albumart workers Jan 10 23:41:59 music volumio[536]: Starting albumart workers Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=debug msg="completed keyexchange" Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=debug msg="completed challenge" Jan 10 23:41:59 music volumio[538]: Starting albumart workers Jan 10 23:41:59 music go-librespot[595]: time="2026-01-10T23:41:59-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:41:59 music volumio[438]: info: MPD Permissions set Jan 10 23:41:59 music volumio[438]: info: MPD Permissions set Jan 10 23:41:59 music volumio[438]: info: Volumio called home Jan 10 23:41:59 music volumio[438]: info: Spotify config file written Jan 10 23:42:00 music sudo[632]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:42:00 music sudo[632]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:00 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:42:00 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:42:00 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:00 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:00 music go-librespot[634]: go-librespot daemon starting... Jan 10 23:42:00 music sudo[632]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42:00-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42:00-05:00" level=debug msg="app state loaded" Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:00 music volumio[438]: info: No need to fix Spotify hosts Jan 10 23:42:00 music volumio[438]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:00 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42: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-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42:00-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]" Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42:00-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]" Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42:00-05:00" level=info msg="zeroconf server listening on port 44227" Jan 10 23:42:00 music go-librespot[635]: time="2026-01-10T23:42:00-05:00" level=debug msg="obtained new client token: AAC0kRbVnJSZLzlOkYHHsVdHgoRBglxCBTs2BYowepYW+Jru0BVXaUEcPGap3Jk3mEUewP+/6u9+JAA0FDTAUe4vKdzucRcJXoG0xV8vps4ocWEdRH3t1YyPxm+olrZ+Yqz5+6TACndDKqoy2xw05mrOG2Bj0ct4siYBracmLwVozDJbhlTXMj6zf/q13I5u4zBnObVtsybgLgbnypt0nbuirPl4qQf/4fCostG84iGeHSFit73C6Fg=" Jan 10 23:42:00 music volumio[438]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=debug msg="completed challenge" Jan 10 23:42:01 music volumio[438]: info: Listing playlists Jan 10 23:42:01 music volumio[438]: info: Listing playlists Jan 10 23:42:01 music volumio[438]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 10 23:42:01 music volumio[438]: info: Starting Shairport Sync Jan 10 23:42:01 music volumio[438]: info: Starting Shairport Sync Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:01 music volumio[438]: info: Starting Shairport Sync Jan 10 23:42:01 music sudo[678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:42:01 music sudo[678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:01 music sudo[680]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:42:01 music sudo[680]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:01 music sudo[683]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:42:01 music sudo[683]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:01 music volumio[438]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:01 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:01 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 23:42:01 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 23:42:01 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:42:01 music systemd[1]: shairport-sync.service: Consumed 1.853s CPU time. Jan 10 23:42:01 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:42:01 music sudo[683]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:01 music sudo[680]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:01 music sudo[678]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:01 music volumio[438]: info: Shairport-Sync Started Jan 10 23:42:01 music volumio[438]: Error adding Membership: Error: addMembership EINVAL Jan 10 23:42:01 music volumio[438]: info: Shairport-Sync Started Jan 10 23:42:01 music volumio[438]: info: Shairport-Sync Started Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=debug msg="completed challenge" Jan 10 23:42:01 music go-librespot[635]: time="2026-01-10T23:42:01-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:02 music go-librespot[635]: time="2026-01-10T23:42:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:42:02 music go-librespot[635]: time="2026-01-10T23:42:02-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:02 music go-librespot[635]: time="2026-01-10T23:42:02-05:00" level=debug msg="completed challenge" Jan 10 23:42:02 music go-librespot[635]: time="2026-01-10T23:42:02-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:02 music mpd[627]: 2026-01-10T23:42:02 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 23:42:02 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 23:42:02 music sudo[577]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:02 music sudo[588]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:02 music volumio[438]: info: Completed starting Core Plugins Jan 10 23:42:02 music volumio[438]: info: ------------------------------------------- Jan 10 23:42:02 music volumio[438]: info: ----- MyVolumio plugins startup ---- Jan 10 23:42:02 music volumio[438]: info: ------------------------------------------- Jan 10 23:42:02 music volumio[438]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 10 23:42:02 music volumio[438]: error: MPD error: The expression evaluated to a falsy value: Jan 10 23:42:02 music volumio[438]: assert.ok(self.idling) Jan 10 23:42:02 music volumio[438]: error: The expression evaluated to a falsy value: Jan 10 23:42:02 music volumio[438]: assert.ok(self.idling) Jan 10 23:42:02 music volumio[438]: error: updateQueue error: null Jan 10 23:42:02 music volumio[438]: info: MPD running with PID627 Jan 10 23:42:02 music volumio[438]: ,establishing connection Jan 10 23:42:02 music volumio[438]: error: updateQueue error: null Jan 10 23:42:03 music go-librespot[635]: time="2026-01-10T23:42:03-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:42:03 music go-librespot[635]: time="2026-01-10T23:42:03-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:03 music go-librespot[635]: time="2026-01-10T23:42:03-05:00" level=debug msg="completed challenge" Jan 10 23:42:03 music go-librespot[635]: time="2026-01-10T23:42:03-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:03 music sudo[726]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:42:03 music sudo[726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:03 music sudo[728]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:42:03 music sudo[728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:03 music sudo[726]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:03 music sudo[728]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:03 music sudo[730]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 23:42:03 music sudo[730]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:03 music sudo[730]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:03 music volumio[438]: info: Upmpdcli Daemon Started Jan 10 23:42:03 music go-librespot[635]: time="2026-01-10T23:42:03-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:42:03 music volumio[438]: info: go-librespot daemon successfully initialized Jan 10 23:42:04 music go-librespot[635]: time="2026-01-10T23:42:04-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:04 music go-librespot[635]: time="2026-01-10T23:42:04-05:00" level=debug msg="completed challenge" Jan 10 23:42:04 music go-librespot[635]: time="2026-01-10T23:42:04-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:05 music go-librespot[635]: time="2026-01-10T23:42:05-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 10 23:42:05 music go-librespot[635]: time="2026-01-10T23:42:05-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:05 music go-librespot[635]: time="2026-01-10T23:42:05-05:00" level=debug msg="completed challenge" Jan 10 23:42:05 music go-librespot[635]: time="2026-01-10T23:42:05-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:05 music go-librespot[635]: time="2026-01-10T23:42: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 " Jan 10 23:42:05 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:42:05 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:42:05 music sudo[738]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:42:05 music sudo[738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:05 music sudo[740]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:42:05 music sudo[740]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:05 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 23:42:05 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 23:42:05 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 23:42:06 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 23:42:06 music sudo[740]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:06 music sudo[738]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:06 music mpd_monitor.sh[743]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 23:42:06 music volumio[438]: info: Successfully started MPD Monitor Jan 10 23:42:06 music volumio[438]: info: Successfully started MPD Monitor Jan 10 23:42:06 music volumio[438]: info: Initializing connection to go-librespot Websocket Jan 10 23:42:07 music volumio[438]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 23:42:07 music volumio[438]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 10 23:42:08 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 10 23:42:08 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:08 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:08 music go-librespot[747]: go-librespot daemon starting... Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42:08-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42:08-05:00" level=debug msg="app state loaded" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42: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]" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42: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]" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42: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]" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42:08-05:00" level=info msg="zeroconf server listening on port 42443" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42:08-05:00" level=debug msg="obtained new client token: AAAZlh2uXxuzZZMbXm0MtG0sseNtDmu0VEoXjiJlT+iwu1ByOJ51fxrgN3gP2b9AJXF8QQXqJZ786uHGeHIuKGG4oHKiMPU+jd8BIu48YiwYsLx201PXzLw9MwbCmNeyXT3eVTH+fPplB4cx23oKxxNoPHiNwB1sB2ymcFO3SajtexUBrm3ZdD+uesXWHDtVh0ScgkqZoIh4D9frKCalNBYGW1OQXQTGhsJAYtSchE6EY/xUsU3O36k=" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42:08-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" Jan 10 23:42:08 music go-librespot[748]: time="2026-01-10T23:42:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:42:09 music go-librespot[748]: time="2026-01-10T23:42:09-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:09 music go-librespot[748]: time="2026-01-10T23:42:09-05:00" level=debug msg="completed challenge" Jan 10 23:42:09 music go-librespot[748]: time="2026-01-10T23:42:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:09 music go-librespot[748]: time="2026-01-10T23:42:09-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:42:09 music go-librespot[748]: time="2026-01-10T23:42:09-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:09 music go-librespot[748]: time="2026-01-10T23:42:09-05:00" level=debug msg="completed challenge" Jan 10 23:42:09 music go-librespot[748]: time="2026-01-10T23:42:09-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:09 music volumio[438]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:09 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:10 music volumio[438]: info: Initializing connection to go-librespot Websocket Jan 10 23:42:10 music go-librespot[748]: time="2026-01-10T23:42:10-05:00" level=debug msg="new websocket client" Jan 10 23:42:10 music volumio[438]: info: Connection to go-librespot Websocket established Jan 10 23:42:10 music go-librespot[748]: time="2026-01-10T23:42:10-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:42:10 music go-librespot[748]: time="2026-01-10T23:42:10-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:10 music go-librespot[748]: time="2026-01-10T23:42:10-05:00" level=debug msg="completed challenge" Jan 10 23:42:10 music go-librespot[748]: time="2026-01-10T23:42:10-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 10 23:42:11 music volumio[438]: info: Adding plugin bluetooth to MyMusic Plugins Jan 10 23:42:11 music volumio[438]: info: Adding plugin multiroom to MyMusic Plugins Jan 10 23:42:11 music volumio[438]: info: Adding plugin metavolumio to MyMusic Plugins Jan 10 23:42:11 music volumio[438]: info: Adding plugin cd_controller to MyMusic Plugins Jan 10 23:42:11 music volumio[438]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 10 23:42:11 music volumio[438]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 10 23:42:11 music volumio[438]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 10 23:42:11 music volumio[438]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 10 23:42:11 music go-librespot[748]: time="2026-01-10T23:42:11-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:42:12 music volumio[438]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 10 23:42:12 music volumio[438]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 10 23:42:12 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:12 music volumio[438]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:12 music volumio[438]: info: Starting MyVolumio Remote Streaming Endpoints Jan 10 23:42:12 music volumio[438]: info: MyVolumio login type: Token Jan 10 23:42:12 music volumio[438]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 10 23:42:12 music volumio[438]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 10 23:42:13 music go-librespot[748]: time="2026-01-10T23:42:13-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:13 music go-librespot[748]: time="2026-01-10T23:42:13-05:00" level=debug msg="completed challenge" Jan 10 23:42:13 music volumio[438]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 10 23:42:13 music volumio[438]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 10 23:42:13 music volumio[438]: info: Streaming services startup Jan 10 23:42:13 music volumio[438]: info: Starting Streaming Daemon Jan 10 23:42:13 music sudo[759]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 10 23:42:13 music sudo[759]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:13 music volumio[438]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 10 23:42:13 music go-librespot[748]: time="2026-01-10T23:42:13-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:13 music sudo[759]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:13 music volumio[438]: info: Getting Spotify volume Jan 10 23:42:13 music volumio[438]: error: Cannot start Volumio Streaming Daemon Jan 10 23:42:13 music volumio[438]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 10 23:42:13 music volumio[438]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 10 23:42:13 music volumio[438]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Jan 10 23:42:13 music volumio[438]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:13 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:13 music volumio[438]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Jan 10 23:42:13 music volumio[438]: SPOTIFY: SPOTIFY VOLUME undefined Jan 10 23:42:13 music volumio[438]: SPOTIFY: VOLUMIO VOLUME 86 Jan 10 23:42:13 music volumio[438]: info: Aligning Spotify Volume to Volumio Volume Jan 10 23:42:13 music volumio[438]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:13 music volumio[438]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:13 music volumio[438]: info: Setting Spotify Volume from Volumio: 86 Jan 10 23:42:13 music volumio[438]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jan 10 23:42:13 music go-librespot[748]: time="2026-01-10T23:42:13-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 10 23:42:14 music volumio[438]: info: MyVolumio token set successfully Jan 10 23:42:14 music volumio[438]: info: MYVOLUMIO: Adding device Jan 10 23:42:14 music volumio[438]: info: MYVOLUMIO: Evaluating Server Jan 10 23:42:14 music go-librespot[748]: time="2026-01-10T23:42:14-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:14 music go-librespot[748]: time="2026-01-10T23:42:14-05:00" level=debug msg="completed challenge" Jan 10 23:42:14 music volumio[438]: info: MyVolumio status changed Jan 10 23:42:14 music volumio[438]: info: Streaming services startup Jan 10 23:42:14 music volumio[438]: info: Starting Streaming Daemon Jan 10 23:42:14 music volumio[438]: info: Removing browser output: myVolumio user plan is not superstar Jan 10 23:42:14 music volumio[438]: info: Removing audio output: Jan 10 23:42:14 music volumio[438]: info: Stoppping Tunnel 1 Jan 10 23:42:14 music sudo[806]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 10 23:42:14 music sudo[806]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:14 music sudo[806]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:14 music go-librespot[748]: time="2026-01-10T23:42:14-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:14 music volumio[438]: error: Cannot start Volumio Streaming Daemon Jan 10 23:42:14 music volumio[438]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jan 10 23:42:14 music volumio[438]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jan 10 23:42:14 music sudo[809]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Jan 10 23:42:14 music sudo[809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:14 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. Jan 10 23:42:14 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. Jan 10 23:42:14 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. Jan 10 23:42:14 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. Jan 10 23:42:14 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. Jan 10 23:42:14 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. Jan 10 23:42:14 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. Jan 10 23:42:14 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. Jan 10 23:42:14 music sudo[809]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:14 music volumio[438]: info: Remote SSH Stopped Jan 10 23:42:15 music volumio[438]: SPOTIFY: SETTING SPOTIFY VOLUME 86 Jan 10 23:42:15 music volumio[438]: info: Sending Spotify command with payload to local API: /player/volume Jan 10 23:42:15 music go-librespot[748]: time="2026-01-10T23:42:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:42:15 music go-librespot[748]: time="2026-01-10T23:42:15-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:15 music go-librespot[748]: time="2026-01-10T23:42:15-05:00" level=debug msg="completed challenge" Jan 10 23:42:15 music go-librespot[748]: time="2026-01-10T23:42:15-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:15 music go-librespot[748]: time="2026-01-10T23:42:15-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 " Jan 10 23:42:15 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:42:15 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:42:15 music volumio[438]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Jan 10 23:42:15 music volumio[438]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:42:15 music volumio[438]: Error: socket hang up Jan 10 23:42:15 music volumio[438]: at connResetException (node:internal/errors:720:14) Jan 10 23:42:15 music volumio[438]: at Socket.socketOnEnd (node:_http_client:519:23) Jan 10 23:42:15 music volumio[438]: at Socket.emit (node:events:526:35) Jan 10 23:42:15 music volumio[438]: at endReadableNT (node:internal/streams/readable:1376:12) Jan 10 23:42:15 music volumio[438]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Jan 10 23:42:15 music volumio[438]: code: 'ECONNRESET', Jan 10 23:42:15 music volumio[438]: response: undefined Jan 10 23:42:15 music volumio[438]: } Jan 10 23:42:15 music volumio[438]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:42:16 music sudo[825]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 23:41' Jan 10 23:42:16 music sudo[825]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:16 music sudo[825]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:18 music volumio-remote-updater[22000]: [2026-01-10 23:42:18] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Jan 10 23:42:18 music systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:42:18 music volumio-remote-updater[22000]: [2026-01-10 23:42:18] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Jan 10 23:42:18 music systemd[1]: volumio.service: Failed with result 'exit-code'. Jan 10 23:42:18 music systemd[1]: volumio.service: Consumed 27.655s CPU time. Jan 10 23:42:18 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:42:18 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:42:18 music systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4338. Jan 10 23:42:18 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Jan 10 23:42:18 music systemd[1]: Started dynamicswap.service - dynamicswap service. Jan 10 23:42:18 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:18 music systemd[1]: Stopped volumio.service - Volumio Backend Module. Jan 10 23:42:18 music systemd[1]: volumio.service: Consumed 27.655s CPU time. Jan 10 23:42:18 music systemd[1]: Started volumio.service - Volumio Backend Module. Jan 10 23:42:18 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:18 music go-librespot[844]: go-librespot daemon starting... Jan 10 23:42:18 music systemd[1]: dynamicswap.service: Deactivated successfully. Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-05:00" level=debug msg="app state loaded" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-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]" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-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]" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-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]" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-05:00" level=info msg="zeroconf server listening on port 45547" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-05:00" level=debug msg="obtained new client token: AACWaaFPOIY0PwI1Yd46EpaJ0mfg50n3r2CGRrEe/km5WlAViRTMb91fLMpArnkVYkrK0dCdKg/afIOFzXR28m8lm0hsRo91ZHfpgLUD61VRb8cfDd9qsVh0PCJg6oBdkB+8em5kCRtsGJLFF+fZs4Su89cp16ipOO4tqdLFSIhuQjCrnxvr9TnbV2ONE2JF4hcitAt2bFkSoQoUqM6W0aLh69yOhjbrZIfI9ewdpb6OZ008FcKZFDg=" Jan 10 23:42:18 music go-librespot[847]: time="2026-01-10T23:42:18-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" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=debug msg="completed challenge" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=debug msg="completed challenge" Jan 10 23:42:19 music go-librespot[847]: time="2026-01-10T23:42:19-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:20 music volumio[840]: info: ------------------------------------------- Jan 10 23:42:20 music volumio[840]: info: ----- Volumio3 ---- Jan 10 23:42:20 music volumio[840]: info: ------------------------------------------- Jan 10 23:42:20 music volumio[840]: info: ----- System startup ---- Jan 10 23:42:20 music volumio[840]: info: ------------------------------------------- Jan 10 23:42:20 music go-librespot[847]: time="2026-01-10T23:42:20-05:00" level=debug msg="connected to ap-gew1.spotify.com:443" Jan 10 23:42:20 music go-librespot[847]: time="2026-01-10T23:42:20-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:20 music go-librespot[847]: time="2026-01-10T23:42:20-05:00" level=debug msg="completed challenge" Jan 10 23:42:20 music go-librespot[847]: time="2026-01-10T23:42:20-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:21 music volumio[840]: info: MYVOLUMIO Environment detected Jan 10 23:42:21 music volumio[840]: info: Plugin folders cleanup Jan 10 23:42:21 music volumio[840]: info: Scanning into folder /volumio/app/plugins/ Jan 10 23:42:21 music volumio[840]: info: Scanning category audio_interface Jan 10 23:42:21 music volumio[840]: info: Scanning category miscellanea Jan 10 23:42:21 music volumio[840]: info: Scanning category music_service Jan 10 23:42:21 music volumio[840]: info: Scanning category plugins.json Jan 10 23:42:21 music volumio[840]: info: Scanning category system_controller Jan 10 23:42:21 music volumio[840]: info: Scanning category user_interface Jan 10 23:42:21 music volumio[840]: info: Scanning into folder /data/plugins/ Jan 10 23:42:21 music volumio[840]: info: Scanning category music_service Jan 10 23:42:21 music volumio[840]: info: Plugin folders cleanup completed Jan 10 23:42:21 music volumio[840]: info: ------------------------------------------- Jan 10 23:42:21 music volumio[840]: info: ----- Core plugins startup ---- Jan 10 23:42:21 music volumio[840]: info: ------------------------------------------- Jan 10 23:42:21 music volumio[840]: info: Loading plugins from folder /volumio/app/plugins/ Jan 10 23:42:21 music volumio[840]: info: Adding plugin upnp to MyMusic Plugins Jan 10 23:42:21 music volumio[840]: info: Adding plugin airplay_emulation to MyMusic Plugins Jan 10 23:42:21 music volumio[840]: info: Adding plugin upnp_browser to MyMusic Plugins Jan 10 23:42:21 music volumio[840]: info: Loading plugins from folder /data/plugins/ Jan 10 23:42:21 music volumio[840]: info: Loading plugin "system"... Jan 10 23:42:21 music volumio[840]: info: Loading plugin "appearance"... Jan 10 23:42:21 music go-librespot[847]: time="2026-01-10T23:42:21-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 10 23:42:21 music go-librespot[847]: time="2026-01-10T23:42:21-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:21 music go-librespot[847]: time="2026-01-10T23:42:21-05:00" level=debug msg="completed challenge" Jan 10 23:42:21 music go-librespot[847]: time="2026-01-10T23:42:21-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:22 music go-librespot[847]: time="2026-01-10T23:42:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:42:22 music go-librespot[847]: time="2026-01-10T23:42:22-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:22 music go-librespot[847]: time="2026-01-10T23:42:22-05:00" level=debug msg="completed challenge" Jan 10 23:42:22 music go-librespot[847]: time="2026-01-10T23:42:22-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:22 music volumio[840]: info: Loading plugin "network"... Jan 10 23:42:22 music volumio[840]: info: Refreshing Cached IP Addresses Jan 10 23:42:22 music sudo[884]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:42:22 music sudo[884]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:22 music sudo[884]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:22 music sudo[886]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:42:22 music sudo[886]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:22 music volumio[840]: info: Loading plugin "services"... Jan 10 23:42:22 music sudo[886]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:22 music volumio[840]: info: Loading plugin "alsa_controller"... Jan 10 23:42:22 music sudo[895]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Jan 10 23:42:22 music sudo[895]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:22 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:42:22 music volumio[840]: info: Loading plugin "wizard"... Jan 10 23:42:22 music volumio[840]: info: Loading plugin "networkfs"... Jan 10 23:42:22 music volumio[840]: info: Starting Udev Watcher for removable devices Jan 10 23:42:22 music volumio[840]: info: Ignoring mount for partition: boot Jan 10 23:42:22 music volumio[840]: info: Ignoring mount for partition: volumio Jan 10 23:42:22 music volumio[840]: info: Ignoring mount for partition: volumio_data Jan 10 23:42:22 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:42:22 music volumio[840]: info: Loading plugin "volumio_command_line_client"... Jan 10 23:42:22 music volumio[840]: info: Loading plugin "upnp"... Jan 10 23:42:22 music volumio[840]: info: [1768106542640] Starting Upmpd Daemon Jan 10 23:42:22 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:42:22 music volumio[840]: info: Loading plugin "my_music"... Jan 10 23:42:22 music volumio[840]: info: Loading plugin "mpd"... Jan 10 23:42:22 music go-librespot[847]: time="2026-01-10T23:42:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:42:22 music go-librespot[847]: time="2026-01-10T23:42:22-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:22 music go-librespot[847]: time="2026-01-10T23:42:22-05:00" level=debug msg="completed challenge" Jan 10 23:42:23 music volumio[840]: info: Loading plugin "upnp_browser"... Jan 10 23:42:23 music go-librespot[847]: time="2026-01-10T23:42:23-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:23 music go-librespot[847]: time="2026-01-10T23:42:23-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 " Jan 10 23:42:23 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:42:23 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:42:23 music volumio-remote-updater[22000]: [2026-01-10 23:42:23] [connect] Successful connection Jan 10 23:42:23 music sudo[895]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:24 music volumio[840]: info: Starting UPNP Browser Jan 10 23:42:24 music volumio[840]: info: Loading plugin "alarm-clock"... Jan 10 23:42:24 music volumio[840]: info: Loading plugin "airplay_emulation"... Jan 10 23:42:24 music volumio[840]: info: Starting Shairport Sync Jan 10 23:42:24 music volumio[840]: info: Loading plugin "last_100"... Jan 10 23:42:24 music volumio[840]: info: Loading plugin "webradio"... Jan 10 23:42:24 music volumio[840]: info: Loading plugin "i2s_dacs"... Jan 10 23:42:24 music volumio[840]: info: I2S DAC not set, start Auto-detection Jan 10 23:42:24 music volumio[840]: info: Loading plugin "volumiodiscovery"... Jan 10 23:42:24 music volumio[840]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:42:24 music volumio[840]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:42:24 music volumio[840]: *** WARNING *** For more information see Jan 10 23:42:24 music volumio[840]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:42:24 music volumio[840]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:42:24 music volumio[840]: *** WARNING *** For more information see Jan 10 23:42:24 music node[840]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Jan 10 23:42:24 music node[840]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:42:24 music node[840]: *** WARNING *** For more information see Jan 10 23:42:24 music node[840]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Jan 10 23:42:24 music node[840]: *** WARNING *** Please fix your application to use the native API of Avahi! Jan 10 23:42:24 music node[840]: *** WARNING *** For more information see Jan 10 23:42:24 music volumio[840]: info: Applying required configuration parameters for plugin volumiodiscovery Jan 10 23:42:24 music volumio[840]: info: Discovery: Started advertising with name: music Jan 10 23:42:24 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jan 10 23:42:24 music volumio[840]: info: Loading plugin "spop"... Jan 10 23:42:26 music volumio[840]: info: Loading plugin "outputs"... Jan 10 23:42:26 music volumio[840]: info: Loading plugin "albumart"... Jan 10 23:42:26 music volumio[840]: info: Plugin example_plugin is not enabled Jan 10 23:42:26 music volumio[840]: info: Loading plugin "inputs"... Jan 10 23:42:26 music volumio[840]: info: Loading plugin "updater_comm"... Jan 10 23:42:26 music volumio[840]: info: Plugin mpdemulation is not enabled Jan 10 23:42:26 music volumio[840]: info: Loading plugin "rest_api"... Jan 10 23:42:26 music volumio[840]: info: Loading plugin "websocket"... Jan 10 23:42:26 music volumio[840]: info: Starting Socket.io Server version 1.7.4 Jan 10 23:42:26 music volumio[840]: info: Loading i18n strings for locale en Jan 10 23:42:26 music volumio[840]: Updating browse sources language Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:42:26 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Jan 10 23:42:26 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:26 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:26 music go-librespot[936]: go-librespot daemon starting... Jan 10 23:42:26 music go-librespot[937]: time="2026-01-10T23:42:26-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:42:26 music go-librespot[937]: time="2026-01-10T23:42:26-05:00" level=debug msg="app state loaded" Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:42:26 music go-librespot[937]: time="2026-01-10T23:42:26-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::initPlayerControls Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:42:26 music volumio[840]: Express server listening on port 3000 Jan 10 23:42:26 music volumio[840]: [Metrics] WebUI: 6s 573.37ms Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::resetVolumioState Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::getcurrentVolume Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:26 music volumio[840]: info: Volumio Network Manager: Network status updated: 1 Jan 10 23:42:26 music volumio-remote-updater[22000]: [2026-01-10 23:42:26] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1768106543 101 Jan 10 23:42:26 music volumio[925]: Forking 3 albumart workers Jan 10 23:42:26 music volumio[840]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Jan 10 23:42:26 music volumio[840]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::pushState Jan 10 23:42:26 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::volumioPushState Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::updateTrackBlock Jan 10 23:42:26 music volumio[840]: info: CorePlayQueue::getTrackBlock Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::volumioRetrievevolume Jan 10 23:42:26 music volumio[840]: info: Reloading queue from file Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::setRepeat null single undefined Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::pushState Jan 10 23:42:26 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::volumioPushState Jan 10 23:42:26 music go-librespot[937]: time="2026-01-10T23:42:26-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]" Jan 10 23:42:26 music go-librespot[937]: time="2026-01-10T23:42:26-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]" Jan 10 23:42:26 music go-librespot[937]: time="2026-01-10T23:42:26-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]" Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::setRandom null Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::pushState Jan 10 23:42:26 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::volumioPushState Jan 10 23:42:26 music volumio[840]: info: Setting Device type: Raspberry PI Jan 10 23:42:26 music go-librespot[937]: time="2026-01-10T23:42:26-05:00" level=info msg="zeroconf server listening on port 37105" Jan 10 23:42:26 music volumio[840]: info: VolumeController:: Volume=86 Mute =false Jan 10 23:42:26 music volumio[840]: info: CoreStateMachine::pushState Jan 10 23:42:26 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::volumioPushState Jan 10 23:42:26 music volumio[840]: info: Discovery: adding 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:42:26 music volumio[840]: info: Discovery: Found device music Jan 10 23:42:26 music volumio[840]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:26 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:26 music volumio[840]: info: Completed loading Core Plugins Jan 10 23:42:26 music volumio[840]: info: Preparing to generate the ALSA configuration file Jan 10 23:42:27 music volumio[840]: info: Discovery: this is already registered, 4a29b7a7-c637-4926-a2bd-fb4e2f55145e Jan 10 23:42:27 music volumio[840]: info: Discovery: Found device music Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:27 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=debug msg="obtained new client token: AAAIJhOeRnk3uDCYLM77oneH92H80nf8B5kgr5J6P7SrRtksjMdnTs/A3s1m+YxiyP1LHmPZNFstD/vIhRXbEwQhqQcj8+s0Y+1VmOc2yKVoIVZtv0XrvbkJ1/rEkIkCRbTfzN8Hu+IgztW/AqPcSrBsWcWfZlal1mltoohY1YfEsn3phihvL646J5s2LuVKnD9kZGZGsbdJZJ+KNM/n8sCHPWyuHriZHwaWax8XXq6ixdltv209kxs=" Jan 10 23:42:27 music volumio[840]: info: Asound.conf file unchanged, so no further update is needed Jan 10 23:42:27 music volumio[840]: info: Output device has changed, restarting MPD Jan 10 23:42:27 music volumio[840]: info: Output device has changed, restarting Shairport Sync Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:27 music volumio[840]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:42:27 music volumio[840]: info: ___________ START PLUGINS ___________ Jan 10 23:42:27 music volumio[840]: info: ControllerMpd::onStart: Initializing MPD Jan 10 23:42:27 music volumio[840]: info: Creating MPD Configuration file Jan 10 23:42:27 music sudo[1001]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:42:27 music sudo[1002]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:42:27 music sudo[1002]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:27 music sudo[1001]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:27 music sudo[1001]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:42:27 music volumio[840]: info: [1768106547128] CoreMusicLibrary::Adding element Media Servers Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:42:27 music sudo[1014]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jan 10 23:42:27 music sudo[1014]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:27 music sudo[1014]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:27 music volumio[840]: info: UPNP Browser: Client initialized successfully Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=debug msg="completed challenge" Jan 10 23:42:27 music systemd[1]: Stopping mpd.service - Music Player Daemon... Jan 10 23:42:27 music sudo[1016]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jan 10 23:42:27 music sudo[1016]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:27 music systemd[1]: mpd.service: Deactivated successfully. Jan 10 23:42:27 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 23:42:27 music systemd[1]: mpd.service: Consumed 4.173s CPU time. Jan 10 23:42:27 music systemd[1]: mpd.socket: Deactivated successfully. Jan 10 23:42:27 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 23:42:27 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 23:42:27 music volumio[840]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:27 music volumio[840]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:42:27 music volumio[840]: info: [1768106547361] CoreMusicLibrary::Adding element Last_100 Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jan 10 23:42:27 music volumio[840]: info: [1768106547365] CoreMusicLibrary::Adding element Webradio Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jan 10 23:42:27 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 23:42:27 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:42:27 music volumio[840]: info: Initializing BBC Radios Jan 10 23:42:27 music systemd[1]: mpd.service: Deactivated successfully. Jan 10 23:42:27 music systemd[1]: Stopped mpd.service - Music Player Daemon. Jan 10 23:42:27 music systemd[1]: mpd.socket: Deactivated successfully. Jan 10 23:42:27 music systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Jan 10 23:42:27 music systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Jan 10 23:42:27 music systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Jan 10 23:42:27 music systemd[1]: Starting mpd.service - Music Player Daemon... Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:27 music volumio[840]: info: Creating Spotify config file Jan 10 23:42:27 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:27 music sudo[1033]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jan 10 23:42:27 music sudo[1033]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jan 10 23:42:27 music sudo[1033]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=debug msg="completed challenge" Jan 10 23:42:27 music go-librespot[937]: time="2026-01-10T23:42:27-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:28 music volumio[840]: info: Volumio Calling Home Jan 10 23:42:28 music go-librespot[937]: time="2026-01-10T23:42:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:42:28 music volumio[952]: Starting albumart workers Jan 10 23:42:28 music go-librespot[937]: time="2026-01-10T23:42:28-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:28 music go-librespot[937]: time="2026-01-10T23:42:28-05:00" level=debug msg="completed challenge" Jan 10 23:42:28 music volumio[950]: Starting albumart workers Jan 10 23:42:28 music go-librespot[937]: time="2026-01-10T23:42:28-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:28 music volumio[840]: info: MPD Permissions set Jan 10 23:42:28 music volumio[840]: info: MPD Permissions set Jan 10 23:42:28 music volumio[840]: info: Volumio called home Jan 10 23:42:28 music volumio[840]: info: Spotify config file written Jan 10 23:42:28 music volumio[840]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music sudo[1050]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jan 10 23:42:28 music sudo[1050]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:28 music systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Jan 10 23:42:28 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jan 10 23:42:28 music systemd[1]: go-librespot-daemon.service: Killing process 942 (go-librespot) with signal SIGKILL. Jan 10 23:42:28 music systemd[1]: go-librespot-daemon.service: Deactivated successfully. Jan 10 23:42:28 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:28 music volumio[840]: info: No need to fix Spotify hosts Jan 10 23:42:29 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:29 music go-librespot[1062]: go-librespot daemon starting... Jan 10 23:42:29 music sudo[1050]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=debug msg="app state loaded" Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:42:29 music volumio[953]: Starting albumart workers Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42: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-gew4.spotify.com:80]" Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-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]" Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-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]" Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=info msg="zeroconf server listening on port 33383" Jan 10 23:42:29 music volumio[840]: info: Starting Shairport Sync Jan 10 23:42:29 music volumio[840]: info: Starting Shairport Sync Jan 10 23:42:29 music volumio[840]: info: Starting Shairport Sync Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=debug msg="obtained new client token: AADH1LxJON3C9dWfEyI4YOy46bevePBXZyQStwmAKZI2/YST+SW9Sd6MsgsHsNicOMjB7xXqrMbyPOxmXutfx3yCi7WVuPN4iuYidIGPeBdr7UUMgXyCMGXgeCQ5wwxpgUjFPEQZhTp2sv1aiSCW9CfnaVsp47IyiSUEA2iSMetmof+nPReu0qO9OjZLPHtDjBAZU+tKgzHCEfj089RzLPC+XUSGMHrLo7fNTWrbEiPR+XrRr2RY5CQ=" Jan 10 23:42:29 music sudo[1079]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:42:29 music sudo[1079]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:29 music sudo[1083]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:42:29 music sudo[1082]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jan 10 23:42:29 music sudo[1082]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:29 music sudo[1083]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42: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" Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:42:29 music systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:29 music go-librespot[1063]: time="2026-01-10T23:42:29-05:00" level=debug msg="completed challenge" Jan 10 23:42:29 music systemd[1]: shairport-sync.service: Deactivated successfully. Jan 10 23:42:29 music systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:42:29 music systemd[1]: shairport-sync.service: Consumed 1.886s CPU time. Jan 10 23:42:30 music go-librespot[1063]: time="2026-01-10T23:42:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:30 music systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Jan 10 23:42:30 music sudo[1083]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:30 music sudo[1082]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:30 music sudo[1079]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:30 music volumio[840]: info: An error occurred while refreshing Spotify Token Error: Bad Request Jan 10 23:42:30 music volumio[840]: info: Shairport-Sync Started Jan 10 23:42:30 music volumio[840]: Error adding Membership: Error: addMembership EINVAL Jan 10 23:42:30 music volumio[840]: info: Shairport-Sync Started Jan 10 23:42:30 music volumio[840]: info: Shairport-Sync Started Jan 10 23:42:30 music volumio[840]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:30 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:30 music volumio[840]: info: Listing playlists Jan 10 23:42:30 music volumio[840]: info: Listing playlists Jan 10 23:42:30 music volumio[840]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:30 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:30 music go-librespot[1063]: time="2026-01-10T23:42:30-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:42:30 music go-librespot[1063]: time="2026-01-10T23:42:30-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:30 music go-librespot[1063]: time="2026-01-10T23:42:30-05:00" level=debug msg="completed challenge" Jan 10 23:42:30 music go-librespot[1063]: time="2026-01-10T23:42:30-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:31 music go-librespot[1063]: time="2026-01-10T23:42:31-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:42:31 music go-librespot[1063]: time="2026-01-10T23:42:31-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:31 music go-librespot[1063]: time="2026-01-10T23:42:31-05:00" level=debug msg="completed challenge" Jan 10 23:42:31 music go-librespot[1063]: time="2026-01-10T23:42:31-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:31 music mpd[1045]: 2026-01-10T23:42:31 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jan 10 23:42:31 music systemd[1]: Started mpd.service - Music Player Daemon. Jan 10 23:42:31 music sudo[1002]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:31 music sudo[1016]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:31 music volumio[840]: info: Completed starting Core Plugins Jan 10 23:42:31 music volumio[840]: info: ------------------------------------------- Jan 10 23:42:31 music volumio[840]: info: ----- MyVolumio plugins startup ---- Jan 10 23:42:31 music volumio[840]: info: ------------------------------------------- Jan 10 23:42:31 music volumio[840]: info: [MyVolumio PluginManager] Fetching plans data.... Jan 10 23:42:31 music volumio[840]: error: MPD error: The expression evaluated to a falsy value: Jan 10 23:42:31 music volumio[840]: assert.ok(self.idling) Jan 10 23:42:31 music volumio[840]: error: The expression evaluated to a falsy value: Jan 10 23:42:31 music volumio[840]: assert.ok(self.idling) Jan 10 23:42:31 music volumio[840]: error: updateQueue error: null Jan 10 23:42:31 music volumio[840]: info: MPD running with PID1045 Jan 10 23:42:31 music volumio[840]: ,establishing connection Jan 10 23:42:31 music volumio[840]: error: updateQueue error: null Jan 10 23:42:32 music go-librespot[1063]: time="2026-01-10T23:42:32-05:00" level=debug msg="connected to ap-gae2.spotify.com:443" Jan 10 23:42:32 music go-librespot[1063]: time="2026-01-10T23:42:32-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:32 music go-librespot[1063]: time="2026-01-10T23:42:32-05:00" level=debug msg="completed challenge" Jan 10 23:42:32 music volumio[840]: info: go-librespot daemon successfully initialized Jan 10 23:42:32 music go-librespot[1063]: time="2026-01-10T23:42:32-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:32 music sudo[1135]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jan 10 23:42:32 music sudo[1135]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:32 music sudo[1135]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:32 music sudo[1137]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jan 10 23:42:32 music sudo[1137]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:32 music sudo[1137]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:32 music sudo[1141]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jan 10 23:42:32 music sudo[1141]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:32 music sudo[1141]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:32 music volumio[840]: info: Upmpdcli Daemon Started Jan 10 23:42:33 music go-librespot[1063]: time="2026-01-10T23:42:33-05:00" level=debug msg="connected to ap-gew4.spotify.com:80" Jan 10 23:42:33 music go-librespot[1063]: time="2026-01-10T23:42:33-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:33 music go-librespot[1063]: time="2026-01-10T23:42:33-05:00" level=debug msg="completed challenge" Jan 10 23:42:33 music go-librespot[1063]: time="2026-01-10T23:42:33-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:33 music go-librespot[1063]: time="2026-01-10T23:42:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:42:34 music go-librespot[1063]: time="2026-01-10T23:42:34-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:34 music go-librespot[1063]: time="2026-01-10T23:42:34-05:00" level=debug msg="completed challenge" Jan 10 23:42:34 music go-librespot[1063]: time="2026-01-10T23:42:34-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:34 music go-librespot[1063]: time="2026-01-10T23:42:34-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 " Jan 10 23:42:34 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:42:34 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:42:34 music sudo[1144]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:42:34 music sudo[1144]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:34 music sudo[1146]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Jan 10 23:42:34 music sudo[1146]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:34 music systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Jan 10 23:42:34 music systemd[1]: mpd_monitor.service: Deactivated successfully. Jan 10 23:42:34 music systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Jan 10 23:42:35 music systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Jan 10 23:42:35 music sudo[1144]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:35 music sudo[1146]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:35 music mpd_monitor.sh[1149]: MPD Monitor Service: Starting MPD Monitor Service Jan 10 23:42:35 music volumio[840]: info: Successfully started MPD Monitor Jan 10 23:42:35 music volumio[840]: info: Successfully started MPD Monitor Jan 10 23:42:35 music volumio[840]: info: Initializing connection to go-librespot Websocket Jan 10 23:42:35 music volumio[840]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 23:42:36 music volumio[840]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jan 10 23:42:37 music systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Jan 10 23:42:37 music systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:37 music systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Jan 10 23:42:37 music go-librespot[1153]: go-librespot daemon starting... Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=info msg="running go-librespot 0.6.2" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=debug msg="app state loaded" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=info msg="api server listening on 127.0.0.1:9879" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-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]" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-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]" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-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]" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=info msg="zeroconf server listening on port 32985" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=debug msg="obtained new client token: AAAz2b3OQlecEK9ZVbusQy51nAHgwp3J5PUmz+qaxvaxE+r3hAPtxdWgm4SJQCE+7/qZcpupK1d3ZX5jlCt+xktLFNePDjZxaFJTyzIUXksJsoi6Wh/tg27gw4kuZDpfSLUpN931Z358z8vlRUvm11UIqFExZ7S/LLLXFTP0f3MiC4mQ23s4adjeAqQLM+HJGplC0oFwwJn8IqB2SI6TtWgczEOWFdzkRJDboiE+TFcIqgz6UY52Aac=" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:37 music go-librespot[1154]: time="2026-01-10T23:42:37-05:00" level=debug msg="completed challenge" Jan 10 23:42:38 music go-librespot[1154]: time="2026-01-10T23:42:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:38 music volumio[840]: info: Initializing connection to go-librespot Websocket Jan 10 23:42:38 music go-librespot[1154]: time="2026-01-10T23:42:38-05:00" level=debug msg="new websocket client" Jan 10 23:42:38 music volumio[840]: info: Connection to go-librespot Websocket established Jan 10 23:42:38 music go-librespot[1154]: time="2026-01-10T23:42:38-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:443, retrying with a different AP" error="dial tcp 34.158.255.62:443: connect: connection refused" Jan 10 23:42:38 music go-librespot[1154]: time="2026-01-10T23:42:38-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Jan 10 23:42:38 music go-librespot[1154]: time="2026-01-10T23:42:38-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:38 music go-librespot[1154]: time="2026-01-10T23:42:38-05:00" level=debug msg="completed challenge" Jan 10 23:42:38 music go-librespot[1154]: time="2026-01-10T23:42:38-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:39 music go-librespot[1154]: time="2026-01-10T23:42:39-05:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jan 10 23:42:39 music go-librespot[1154]: time="2026-01-10T23:42:39-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:39 music go-librespot[1154]: time="2026-01-10T23:42:39-05:00" level=debug msg="completed challenge" Jan 10 23:42:39 music go-librespot[1154]: time="2026-01-10T23:42:39-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:39 music volumio[840]: info: CoreCommandRouter::volumioGetState Jan 10 23:42:39 music volumio[840]: info: CorePlayQueue::getTrack 0 Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Jan 10 23:42:40 music volumio[840]: info: Adding plugin bluetooth to MyMusic Plugins Jan 10 23:42:40 music volumio[840]: info: Adding plugin multiroom to MyMusic Plugins Jan 10 23:42:40 music volumio[840]: info: Adding plugin metavolumio to MyMusic Plugins Jan 10 23:42:40 music volumio[840]: info: Adding plugin cd_controller to MyMusic Plugins Jan 10 23:42:40 music volumio[840]: info: Adding plugin qobuzconnect to MyMusic Plugins Jan 10 23:42:40 music volumio[840]: info: Adding plugin smart_inputs to MyMusic Plugins Jan 10 23:42:40 music volumio[840]: info: Adding plugin tidalconnect to MyMusic Plugins Jan 10 23:42:40 music volumio[840]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Jan 10 23:42:40 music go-librespot[1154]: time="2026-01-10T23:42:40-05:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:443, retrying with a different AP" error="dial tcp 104.199.241.202:443: connect: connection refused" Jan 10 23:42:40 music go-librespot[1154]: time="2026-01-10T23:42:40-05:00" level=debug msg="connected to ap-gew1.spotify.com:80" Jan 10 23:42:40 music go-librespot[1154]: time="2026-01-10T23:42:40-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:40 music go-librespot[1154]: time="2026-01-10T23:42:40-05:00" level=debug msg="completed challenge" Jan 10 23:42:40 music go-librespot[1154]: time="2026-01-10T23:42:40-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:41 music volumio[840]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Jan 10 23:42:41 music volumio[840]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Jan 10 23:42:41 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:41 music volumio[840]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jan 10 23:42:41 music volumio[840]: info: Starting MyVolumio Remote Streaming Endpoints Jan 10 23:42:41 music go-librespot[1154]: time="2026-01-10T23:42:41-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Jan 10 23:42:41 music volumio[840]: info: MyVolumio login type: Token Jan 10 23:42:41 music volumio[840]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Jan 10 23:42:41 music volumio[840]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Jan 10 23:42:41 music go-librespot[1154]: time="2026-01-10T23:42:41-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:41 music go-librespot[1154]: time="2026-01-10T23:42:41-05:00" level=debug msg="completed challenge" Jan 10 23:42:41 music go-librespot[1154]: time="2026-01-10T23:42:41-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:41 music go-librespot[1154]: time="2026-01-10T23:42:41-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Jan 10 23:42:41 music go-librespot[1154]: time="2026-01-10T23:42:41-05:00" level=debug msg="completed keyexchange" Jan 10 23:42:41 music go-librespot[1154]: time="2026-01-10T23:42:41-05:00" level=debug msg="completed challenge" Jan 10 23:42:42 music go-librespot[1154]: time="2026-01-10T23:42:42-05:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed authenticating: accesspoint login failed: BadCredentials " Jan 10 23:42:42 music go-librespot[1154]: time="2026-01-10T23:42:42-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 " Jan 10 23:42:42 music systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 10 23:42:42 music systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 10 23:42:42 music volumio[840]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jan 10 23:42:42 music volumio[840]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jan 10 23:42:42 music volumio[840]: info: Streaming services startup Jan 10 23:42:42 music volumio[840]: info: Starting Streaming Daemon Jan 10 23:42:42 music sudo[1164]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jan 10 23:42:42 music sudo[1164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 10 23:42:42 music volumio[840]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jan 10 23:42:42 music sudo[1164]: pam_unix(sudo:session): session closed for user root Jan 10 23:42:42 music volumio[840]: info: Getting Spotify volume Jan 10 23:42:42 music volumio[840]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:42:42 music volumio[840]: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 10 23:42:42 music volumio[840]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Jan 10 23:42:42 music volumio[840]: errno: -111, Jan 10 23:42:42 music volumio[840]: code: 'ECONNREFUSED', Jan 10 23:42:42 music volumio[840]: syscall: 'connect', Jan 10 23:42:42 music volumio[840]: address: '127.0.0.1', Jan 10 23:42:42 music volumio[840]: port: 9879, Jan 10 23:42:42 music volumio[840]: response: undefined Jan 10 23:42:42 music volumio[840]: } Jan 10 23:42:42 music volumio[840]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 10 23:42:43 music sudo[1199]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-10 23:41' Jan 10 23:42:43 music sudo[1199]: 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"