Dec 09 05:54:00 gbvpi-bedroom go-librespot[8225]: time="2025-12-09T05:54:00-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:00 gbvpi-bedroom go-librespot[8225]: time="2025-12-09T05:54:00-05:00" level=debug msg="completed challenge" Dec 09 05:54:00 gbvpi-bedroom go-librespot[8225]: time="2025-12-09T05:54:00-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Loading plugin "outputs"... Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Loading plugin "albumart"... Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Plugin example_plugin is not enabled Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Loading plugin "inputs"... Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Loading plugin "updater_comm"... Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Plugin mpdemulation is not enabled Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Loading plugin "rest_api"... Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Loading plugin "websocket"... Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Starting Socket.io Server version 1.7.4 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Loading i18n strings for locale en Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: Updating browse sources language Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::initPlayerControls Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: Express server listening on port 3000 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: [Metrics] WebUI: 3s 815.60ms Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::resetVolumioState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::getcurrentVolume Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Volumio Network Manager: Network status updated: 2 Dec 09 05:54:00 gbvpi-bedroom volumio-remote-updater[752]: [2025-12-09 05:54:00] [connect] Successful connection Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: VolumeController:: Volume=91 Mute =false Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::pushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioPushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::updateTrackBlock Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrackBlock Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 05:54:00 gbvpi-bedroom volumio[8235]: Forking 3 albumart workers Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Reloading queue from file Dec 09 05:54:00 gbvpi-bedroom volumio-remote-updater[752]: [2025-12-09 05:54:00] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765277640 101 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::setRepeat true single undefined Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::pushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioPushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::setRandom null Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::pushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioPushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Setting Device type: Raspberry PI Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: VolumeController:: Volume=91 Mute =false Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::pushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioPushState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Discovery: adding 357de02c-99c5-4ddd-be16-8ae369ed89c3 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Discovery: Found device NorthPi-Soundstation Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Discovery: Connecting to remote: 192.168.1.28 Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Discovery: adding 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: Discovery: Found device GBVPi-Bedroom Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:00 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Completed loading Core Plugins Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Preparing to generate the ALSA configuration file Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Asound.conf file written Dec 09 05:54:01 gbvpi-bedroom sudo[8292]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 09 05:54:01 gbvpi-bedroom sudo[8292]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:01 gbvpi-bedroom sudo[8292]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Output device has changed, restarting MPD Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Output device has changed, restarting Shairport Sync Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:01 gbvpi-bedroom sudo[8299]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 05:54:01 gbvpi-bedroom sudo[8302]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 05:54:01 gbvpi-bedroom sudo[8302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:01 gbvpi-bedroom sudo[8299]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: ___________ START PLUGINS ___________ Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: ControllerMpd::onStart: Initializing MPD Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Creating MPD Configuration file Dec 09 05:54:01 gbvpi-bedroom sudo[8299]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: [1765277641203] CoreMusicLibrary::Adding element Media Servers Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:54:01 gbvpi-bedroom sudo[8311]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: UPNP Browser: Client initialized successfully Dec 09 05:54:01 gbvpi-bedroom sudo[8311]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:01 gbvpi-bedroom sudo[8313]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 05:54:01 gbvpi-bedroom sudo[8313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:01 gbvpi-bedroom sudo[8311]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:01 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:01 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.281s CPU time. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: [1765277641305] CoreMusicLibrary::Adding element Last_100 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: [1765277641313] CoreMusicLibrary::Adding element Webradio Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Initializing BBC Radios Dec 09 05:54:01 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 05:54:01 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Discovery: Getting this device information Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: [1765277641444] CoreMusicLibrary::Adding element Jellyfin Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: Cannot find translation for source Jellyfin Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: [jellyfin] Initialized plugin with device info: {"host":"http://192.168.1.97","id":"74ce6260-2045-48bb-acbd-0b75ccb5d93e","name":"GBVPi-Bedroom","serviceName":"Volumio","state":{"albumart":"https://jellyfin.lukeaurio.net/Items/2a8b0b42bfe09e9da6781f7cc9edae11/Images/Primary?maxWidth=500&maxHeight=500&quality=90","artist":"King Gizzard & The Lizard Wizard","mute":false,"status":"stop","track":"Mars For The Rich (Live at Red Rocks '22)","volume":91},"type":"device"} Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Creating Spotify config file Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:01 gbvpi-bedroom sudo[8330]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 05:54:01 gbvpi-bedroom sudo[8330]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 05:54:01 gbvpi-bedroom sudo[8330]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Volumio Calling Home Dec 09 05:54:01 gbvpi-bedroom volumio[8257]: Starting albumart workers Dec 09 05:54:01 gbvpi-bedroom volumio[8258]: Starting albumart workers Dec 09 05:54:01 gbvpi-bedroom volumio[8259]: Starting albumart workers Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Discovery: this is already registered, 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: Discovery: Found device GBVPi-Bedroom Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:01 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: MPD Permissions set Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: MPD Permissions set Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Spotify config file written Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom sudo[8347]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 09 05:54:02 gbvpi-bedroom sudo[8347]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:02 gbvpi-bedroom go-librespot[8354]: go-librespot daemon starting... Dec 09 05:54:02 gbvpi-bedroom sudo[8347]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="app state loaded" Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:02 gbvpi-bedroom sudo[8201]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: No need to fix Spotify hosts Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Volumio called home Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=info msg="zeroconf server listening on port 35483" Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Starting Shairport Sync Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Starting Shairport Sync Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Starting Shairport Sync Dec 09 05:54:02 gbvpi-bedroom sudo[8384]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:54:02 gbvpi-bedroom sudo[8384]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:02 gbvpi-bedroom sudo[8380]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:54:02 gbvpi-bedroom sudo[8380]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="obtained new client token: AADusCWPOEF1SvvQI/MYFZjxnsNwKbq2PzWVE3zYNL/wXkcxetzVEqjlx7LvLQKeFCCzPxb0R8R0jnDQwDmG9Zk69r+Bbr6Rz69UZLBWNWncxi3Hg08yokagcAuEYzg3/An8fvxSibsUkngrHjb6wSxdymoArLAuWFrOOOJXXeZYtCO0+fNJSfCuiucfzh79sT8zJ2gyGE6kKweNZwMUHxsarg7tey32BydgBaQwMTnYsJLUiB546L79PQ==" Dec 09 05:54:02 gbvpi-bedroom sudo[8383]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:54:02 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 05:54:02 gbvpi-bedroom sudo[8383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:54:02 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.740s CPU time. Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Dec 09 05:54:02 gbvpi-bedroom sudo[8384]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 05:54:02 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 09 05:54:02 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:54:02 gbvpi-bedroom sudo[8383]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:02 gbvpi-bedroom sudo[8380]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Shairport-Sync Started Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: Error adding Membership: Error: addMembership EINVAL Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=debug msg="completed challenge" Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Shairport-Sync Started Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: Shairport-Sync Started Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:02 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:02 gbvpi-bedroom go-librespot[8355]: time="2025-12-09T05:54:02-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:02 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:02 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:03 gbvpi-bedroom mpd[8342]: 2025-12-09T05:54:03 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 09 05:54:03 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 09 05:54:03 gbvpi-bedroom sudo[8302]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:03 gbvpi-bedroom sudo[8313]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: Completed starting Core Plugins Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: ------------------------------------------- Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: ----- MyVolumio plugins startup ---- Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: ------------------------------------------- Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: error: MPD error: The expression evaluated to a falsy value: Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: assert.ok(self.idling) Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: error: The expression evaluated to a falsy value: Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: assert.ok(self.idling) Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: MPD running with PID8342 Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: ,establishing connection Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: error: updateQueue error: null Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: error: updateQueue error: null Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:03 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:05 gbvpi-bedroom volumio[8163]: info: go-librespot daemon successfully initialized Dec 09 05:54:06 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 350. Dec 09 05:54:06 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:06 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:06 gbvpi-bedroom go-librespot[8415]: go-librespot daemon starting... Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="app state loaded" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=info msg="zeroconf server listening on port 42259" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="obtained new client token: AAA/m9UkLnERAR4OIu6Zg0ZdhnHyuma7eEtKyHh8k7mtfPNA0aWeZQxN6RTMnPDJb8QgcZBNRZRuHTdOk2OEqTnzxVnXpdVwksAQLovXE1ScOD1KIrATzWdl6UdFN/3u1/hL+JY25ky0LByGCa4Swdzletx2s4knFz6OxQ809+j2veLuoU9YPLDw9AMYCOmJ5N4gcLOd81XSlLDDf9AM/GdEv8L0ToyCCbAvZBP8f1sU2AWwlIoq+gziCw==" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:06 gbvpi-bedroom sudo[8424]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 05:54:06 gbvpi-bedroom sudo[8424]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:06 gbvpi-bedroom sudo[8426]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 05:54:06 gbvpi-bedroom sudo[8426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=debug msg="completed challenge" Dec 09 05:54:06 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 09 05:54:06 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 09 05:54:06 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 09 05:54:06 gbvpi-bedroom go-librespot[8416]: time="2025-12-09T05:54:06-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:06 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 09 05:54:06 gbvpi-bedroom sudo[8424]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:06 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:06 gbvpi-bedroom sudo[8426]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:06 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:06 gbvpi-bedroom volumio[8163]: info: Successfully started MPD Monitor Dec 09 05:54:06 gbvpi-bedroom volumio[8163]: info: Successfully started MPD Monitor Dec 09 05:54:06 gbvpi-bedroom mpd_monitor.sh[8429]: MPD Monitor Service: Starting MPD Monitor Service Dec 09 05:54:08 gbvpi-bedroom sudo[8448]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 05:54:08 gbvpi-bedroom sudo[8448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:08 gbvpi-bedroom sudo[8448]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:08 gbvpi-bedroom sudo[8450]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 05:54:08 gbvpi-bedroom sudo[8450]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:08 gbvpi-bedroom sudo[8450]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:08 gbvpi-bedroom sudo[8453]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 09 05:54:08 gbvpi-bedroom sudo[8453]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:08 gbvpi-bedroom sudo[8453]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:08 gbvpi-bedroom volumio[8163]: info: Upmpdcli Daemon Started Dec 09 05:54:08 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:08 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:08 gbvpi-bedroom volumio[8163]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 09 05:54:09 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 351. Dec 09 05:54:09 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:09 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:09 gbvpi-bedroom go-librespot[8456]: go-librespot daemon starting... Dec 09 05:54:09 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:09-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:09 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:09-05:00" level=debug msg="app state loaded" Dec 09 05:54:09 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:09-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=info msg="zeroconf server listening on port 42769" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=debug msg="obtained new client token: AADDTmqOm9oNOM7ZHXi4uHHaKp5fGh0An3JIBe5hzheJSsst2mpUdSRgvgX7HI4ywa51uVWmo8uvSEFPmzPP5uFkVdUepApEr8+fIa1XLlfKbmbXICOK6vY8hoOSk1e/lIQO1/989XnPhcGWbuPLtvodkev3aNlNY4aAArOXZWJK7FjGInB7YFT5XAk8SbJaNKowR1gu4k5GaOjNOhfNviSvW8wCNfKWp2jG2i0d9RYhMH25TczcpFE=" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=debug msg="completed challenge" Dec 09 05:54:10 gbvpi-bedroom go-librespot[8457]: time="2025-12-09T05:54:10-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:10 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:10 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Adding plugin bluetooth to MyMusic Plugins Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Adding plugin multiroom to MyMusic Plugins Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Adding plugin metavolumio to MyMusic Plugins Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Adding plugin cd_controller to MyMusic Plugins Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 09 05:54:11 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: Starting MyVolumio Remote Streaming Endpoints Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: MyVolumio login type: Token Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: Streaming services startup Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: Starting Streaming Daemon Dec 09 05:54:12 gbvpi-bedroom sudo[8465]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 09 05:54:12 gbvpi-bedroom sudo[8465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 09 05:54:12 gbvpi-bedroom sudo[8465]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: error: Cannot start Volumio Streaming Daemon Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 09 05:54:12 gbvpi-bedroom volumio[8163]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 09 05:54:13 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 352. Dec 09 05:54:13 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:13 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:13 gbvpi-bedroom go-librespot[8471]: go-librespot daemon starting... Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=debug msg="app state loaded" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54: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-gew4.spotify.com:80]" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=info msg="zeroconf server listening on port 42337" Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: MyVolumio token set successfully Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: MYVOLUMIO: Adding device Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: MYVOLUMIO: Evaluating Server Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=debug msg="obtained new client token: AAAMaKdkOI9Afmlv4yisbIhS0S3cg8kiAN5mkQvmaCUXYA8aFan4VjboIHQg6D9YhjK59PGGmrD5kXxOThx4mn0ubLzxCOKvZU77zrIStqz1h3bh+EPuvytDvO0vB26VpxKJyMk+yuhX4w5U0nwLjLLSQFbpHx1p5+9MYcvIEu8Gaf5gBAt3oUifJZBX2jKHCW8smykMw7CxH49z+W6chFKfCWXQ1ujOZTo2J92HlZl9Dj+8budmHtxhMQ==" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=debug msg="completed challenge" Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: MyVolumio Plan changed: premium Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: Removing browser output: myVolumio user plan is not superstar Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: Removing audio output: Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: MYVOLUMIO: Adding device Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: MYVOLUMIO: Evaluating Server Dec 09 05:54:13 gbvpi-bedroom go-librespot[8472]: time="2025-12-09T05:54:13-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:13 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:13 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: Remote config written successfully Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: Starting Tunnel 1 Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: Starting Tunnel Connection Checker Dec 09 05:54:13 gbvpi-bedroom volumio[8163]: info: Completed starting MyVolumio Plugin Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: MYVolumio Device enabled Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: MyVolumio status changed Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: Streaming services startup Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: Starting Streaming Daemon Dec 09 05:54:14 gbvpi-bedroom sudo[8518]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 09 05:54:14 gbvpi-bedroom sudo[8518]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: Setting Geolocation for MyVolumio to us1 Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:14 gbvpi-bedroom sudo[8518]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Dec 09 05:54:14 gbvpi-bedroom sudo[8522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 09 05:54:14 gbvpi-bedroom sudo[8522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:14 gbvpi-bedroom sudo[8522]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: MRS: MultiRoom plugin initialized Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: MRS: STOPPING SNAPCLIENT Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: MRS: Snap server stop Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: MRS: STOPPING volumioStreaming Dec 09 05:54:14 gbvpi-bedroom sudo[8540]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 09 05:54:14 gbvpi-bedroom sudo[8540]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:14 gbvpi-bedroom sudo[8542]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 09 05:54:14 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 09 05:54:14 gbvpi-bedroom sudo[8542]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:14 gbvpi-bedroom sudo[8545]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 09 05:54:14 gbvpi-bedroom sudo[8545]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 09 05:54:15 gbvpi-bedroom sudo[8547]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 09 05:54:15 gbvpi-bedroom sudo[8547]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 09 05:54:15 gbvpi-bedroom sudo[8547]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 09 05:54:15 gbvpi-bedroom sudo[8540]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 09 05:54:15 gbvpi-bedroom sudo[8542]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:15 gbvpi-bedroom sudo[8545]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Preparing to generate the ALSA configuration file Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Updating MyVolumio device info Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Setting Geolocation for MyVolumio to us4 Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Reading ALSA contributions from plugins. Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Successfully Added MyVolumio device Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: Removed streaming files Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: volumioStreaming STOPPED Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: SNAPSERVER STOPPED Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: SNAPCLIENT STOPPED Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: error: Cannot start Volumio Streaming Daemon Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Asound.conf file written Dec 09 05:54:15 gbvpi-bedroom sudo[8554]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 09 05:54:15 gbvpi-bedroom sudo[8554]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:15 gbvpi-bedroom sudo[8554]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Output device has changed, restarting MPD Dec 09 05:54:15 gbvpi-bedroom sudo[8560]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 05:54:15 gbvpi-bedroom sudo[8560]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:15 gbvpi-bedroom sudo[8560]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Output device has changed, restarting Shairport Sync Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:15 gbvpi-bedroom sudo[8563]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 05:54:15 gbvpi-bedroom sudo[8563]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: [FUNC] onStart Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Dec 09 05:54:15 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: Pushing multiroomSync output for this device Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: Pushing multiroomSync output Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding audio output: Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding audio output: Dec 09 05:54:15 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 09 05:54:15 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 05:54:15 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.895s CPU time. Dec 09 05:54:15 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 09 05:54:15 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 05:54:15 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:15 gbvpi-bedroom bluetoothd[732]: Path / reserved for Adv Monitor app :1.17083 Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding METAVOLUMIO REST API Endpoints Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 09 05:54:15 gbvpi-bedroom bluetoothd[732]: Adv Monitor app :1.17083 disconnected from D-Bus Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Preparing CD Folders Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding CD REST API Endpoints Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Starting UDEV Watcher for CD Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: Detecting CD presence with UDEV Dec 09 05:54:15 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 09 05:54:15 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 05:54:15 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 05:54:15 gbvpi-bedroom sudo[8577]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 05:54:15 gbvpi-bedroom sudo[8577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 05:54:15 gbvpi-bedroom sudo[8577]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:16 gbvpi-bedroom mpd[8582]: 2025-12-09T05:54:16 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 09 05:54:16 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 09 05:54:16 gbvpi-bedroom sudo[8563]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:17 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 353. Dec 09 05:54:17 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:17 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:17 gbvpi-bedroom go-librespot[8585]: go-librespot daemon starting... Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="app state loaded" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=info msg="zeroconf server listening on port 40241" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="obtained new client token: AAAHVSHbqOwuLRDaotzQNnpGNVUVmzaBhnjLf2jEd2N3mqQ3yVrDWs3Uz0GgmH9rED8GdpRZQEdttL0jV+qTz65b0PrfuDmsDJUR4L4mTE44gIpu2DinmhHgPgmtepz6AQPTl38hmQbwd8wodjTRCEb0rHsUrj3Hdliw7dlcOoJACs2ixNo6yngN31f3F2AZl8G8X6ww+TMLBZi6ShLhA4qBhS/oPVXOWjPGVn7so8v/ONAYnKf7U2MnsA==" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=debug msg="completed challenge" Dec 09 05:54:17 gbvpi-bedroom go-librespot[8586]: time="2025-12-09T05:54:17-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:17 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:17 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding inputs REST Endpoints Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Scanning Audio Inputs Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Checking against Known Cards name Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding Server instance for streaming Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: error: Hi Res Audio Failed Login: Missing Login Data Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Dec 09 05:54:20 gbvpi-bedroom sudo[8612]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: QobuzConnect: Starting Qobuz Connect socket and service Dec 09 05:54:20 gbvpi-bedroom sudo[8612]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding TIDAL REST API Endpoints Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Stopping AccessToken refresher cron for QOBUZ Dec 09 05:54:20 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 354. Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:20 gbvpi-bedroom sudo[8619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 09 05:54:20 gbvpi-bedroom sudo[8619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: AccessToken refresher cron started for QOBUZ Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding QOBUZ REST API Endpoints Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Updating MyVolumio device info Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: MRS: Getting audio outputs on start Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: MRS: Requesting all other devices output Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Successfully Updated MyVolumio device Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:20 gbvpi-bedroom go-librespot[8620]: go-librespot daemon starting... Dec 09 05:54:20 gbvpi-bedroom sudo[8619]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=debug msg="app state loaded" Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:20 gbvpi-bedroom systemd[1]: vtcs.service: Killing process 7906 (vtcs) with signal SIGKILL. Dec 09 05:54:20 gbvpi-bedroom systemd[1]: vtcs.service: Deactivated successfully. Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 09 05:54:20 gbvpi-bedroom sudo[8629]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 09 05:54:20 gbvpi-bedroom sudo[8629]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:20 gbvpi-bedroom sudo[8612]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Successfully Added MyVolumio device Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: MPD Permissions set Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 09 05:54:20 gbvpi-bedroom qobuz-connect[7866]: 20251209 05:54:20.699 [7866.7866] INFO SampleApp: Stopping Local configuration server Dec 09 05:54:20 gbvpi-bedroom sudo[8634]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Dec 09 05:54:20 gbvpi-bedroom sudo[8634]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom sudo[8634]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: error: updateQueue error: null Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioStop Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::stop Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=info msg="zeroconf server listening on port 45241" Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Starting Shairport Sync Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: MRS: Found cast device: Google-Home-Mini-f209fa314cb426d40a59bcf66354ddc9 Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding audio output: Dec 09 05:54:20 gbvpi-bedroom sudo[8650]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 09 05:54:20 gbvpi-bedroom sudo[8650]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Successfully Updated MyVolumio device Dec 09 05:54:20 gbvpi-bedroom sudo[8652]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:54:20 gbvpi-bedroom sudo[8652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: MRS: Found cast device: SmartTV-4K-fe72c264393a59c76d38e27b8168114d Dec 09 05:54:20 gbvpi-bedroom volumio[8163]: info: Adding audio output: Dec 09 05:54:20 gbvpi-bedroom autossh[7840]: received signal to exit (15) Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Dec 09 05:54:20 gbvpi-bedroom systemd[1]: sshtunnel.service: Deactivated successfully. Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=debug msg="obtained new client token: AACLDBW3GeQR1IAkVdWv9HuGxF3xSg8h4SwBsv8A7k7HOuVJHq+GLbhnPhzenwLqQDL0BF6RcQZPZuZZK8YDX62E+84GPyDhBxiJZq0YclvWrLOpwN2EdC3AP8tYfQnGnu7fmQnWMnMGWnztc6vpphmNtaXyD8PISGHVE7d2N6wUn3D6WJH9xhTK/WJ7kUJnD4k1VlCFzv5dHuCWxj/x666FcEFgZjsF6rz9FbuA4b7d2DMN6Vr6feZosA==" Dec 09 05:54:20 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 05:54:20 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:20-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:21 gbvpi-bedroom systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 09 05:54:21 gbvpi-bedroom sudo[8650]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:21 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 05:54:21 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:54:21 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.594s CPU time. Dec 09 05:54:21 gbvpi-bedroom volumio[8163]: info: Remote SSH Started Dec 09 05:54:21 gbvpi-bedroom autossh[8656]: port set to 0, monitoring disabled Dec 09 05:54:21 gbvpi-bedroom autossh[8656]: starting ssh (count 1) Dec 09 05:54:21 gbvpi-bedroom autossh[8656]: ssh child pid is 8659 Dec 09 05:54:21 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:54:21 gbvpi-bedroom sudo[8652]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:21 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:21-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:21 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:21-05:00" level=debug msg="completed challenge" Dec 09 05:54:21 gbvpi-bedroom go-librespot[8624]: time="2025-12-09T05:54:21-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:21 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:21 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:21 gbvpi-bedroom volumio[8163]: info: Shairport-Sync Started Dec 09 05:54:21 gbvpi-bedroom volumio[8163]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 09 05:54:21 gbvpi-bedroom volumiossh-tunnel[8659]: Warning: Permanently added '[us4.myvolumio.org]:2222' (ED25519) to the list of known hosts. Dec 09 05:54:21 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:21 gbvpi-bedroom volumio[8163]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 09 05:54:22 gbvpi-bedroom systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 09 05:54:22 gbvpi-bedroom systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 09 05:54:22 gbvpi-bedroom systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 09 05:54:22 gbvpi-bedroom sudo[8629]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:22 gbvpi-bedroom volumio[8163]: info: Executing endpoint qc_getconfig Dec 09 05:54:22 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.138 [8675.8675] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 09 05:54:22 gbvpi-bedroom volumio[8163]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 09 05:54:22 gbvpi-bedroom volumio[8163]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.143 [8675.8675] INFO VolumeManager: [0x158b588]: Setting new playback volume: 75 Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.143 [8675.8675] INFO VolumeManager: [0x158b588]: Setting new mute state: 0 Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.143 [8675.8675] INFO QobuzConnect: [0x158bf58]: Client initialized! Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.143 [8675.8675] INFO SampleApp: Starting Avahi advertising, name: GBVPi-Bedroom, service name: _qobuz-connect._tcp Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.157 [8675.8675] INFO LocalConfigManager: [0x158ae68]: Starting Local Configuration server Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.157 [8675.8675] INFO SampleApp: Starting Local configuration server Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.158 [8675.8675] INFO SampleApp: Connected to UNIX socket client 0x1575818 Dec 09 05:54:22 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:54:22.287 [8675.8675] INFO SampleApp: Playback volume changed: 75 Dec 09 05:54:22 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: TidalConnect service stoped! Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 09 05:54:23 gbvpi-bedroom sudo[8690]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 05:54:23 gbvpi-bedroom sudo[8690]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:23 gbvpi-bedroom sudo[8692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 09 05:54:23 gbvpi-bedroom sudo[8692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:54:23 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 09 05:54:23 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 09 05:54:23 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 09 05:54:23 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 09 05:54:23 gbvpi-bedroom sudo[8690]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:23 gbvpi-bedroom mpd_monitor.sh[8695]: MPD Monitor Service: Starting MPD Monitor Service Dec 09 05:54:23 gbvpi-bedroom systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 09 05:54:23 gbvpi-bedroom sudo[8692]: pam_unix(sudo:session): session closed for user root Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Successfully started MPD Monitor Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Executing endpoint tc_getconfig Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 09 05:54:23 gbvpi-bedroom vtcs[8699]: STARTING TidalConnect services, version: 1.5.2.56 Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:23 gbvpi-bedroom vtcs[8699]: STARTED TidalConnect services. Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Executing endpoint tc_connect Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: Connecting to TidalConnect Dec 09 05:54:23 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::servicePushState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::pushState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioPushState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: MRS: Pushing multiroomSync output update for this device Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: MRS: Pushing multiroomSync output Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::servicePushState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreStateMachine::pushState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioPushState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: MRS: Pushing multiroomSync output update for this device Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: MRS: Pushing multiroomSync output Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: CorePlayQueue::getTrack 0 Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 09 05:54:24 gbvpi-bedroom volumio[8163]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 09 05:54:24 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 355. Dec 09 05:54:24 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:24 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:24 gbvpi-bedroom go-librespot[8716]: go-librespot daemon starting... Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="app state loaded" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=info msg="zeroconf server listening on port 44095" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="obtained new client token: AAAk58aIo4FYXmBFAwCCt9123b1u0SjJqFSs2nSjsKaiB18h207aCO/TFX2LTwzh99xYUxIx3ZytxnnKYk/2VVdZtsA8wsfrEITd16RpbWDBLlSdusBq7dVcDcB2tLAkJzonI6TRQUCCxZyDYF1HVNVjJknd1po+tK6OAeRBKfBjhLxnV0eAETHiBc12qR/hhYhSxmBP5eT5RApK2vCw/r+QuUxNizAhJ+GeYuee8vn7XyXJ2V7ZcIhC7w==" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=debug msg="completed challenge" Dec 09 05:54:24 gbvpi-bedroom go-librespot[8717]: time="2025-12-09T05:54:24-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:24 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:24 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: TidalConnect service started! Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: [Metrics] CommandRouter: 29s 716.96ms Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumiosetStartupVolume Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::Close All Modals sent Dec 09 05:54:26 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::Close All Modals sent Dec 09 05:54:27 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 09 05:54:27 gbvpi-bedroom volumio[8163]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 09 05:54:27 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:27 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 356. Dec 09 05:54:27 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:27 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:27 gbvpi-bedroom go-librespot[8724]: go-librespot daemon starting... Dec 09 05:54:27 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:27-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:27 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:27-05:00" level=debug msg="app state loaded" Dec 09 05:54:27 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 09 05:54:27 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 09 05:54:27 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:27-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:27 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=info msg="zeroconf server listening on port 44469" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=debug msg="obtained new client token: AADsCbg0p/i69+MSg/2fOdiuvh0C0ZBPH+S/V8uk5eGHJgefZC0Axqh0YT/rFwD/hXhOAaLUsceZIyikoDM32/hYSClBjFaRXOwcviGN9gGXtyMpJxYokuWOg2QfmibuMfHBf94IiQofwJzmCodhhyocITCkj+eaIg3MFEiJrhlN931egYEJS28cbG0P+MKhrMPR5KsyiVgEbGVaO2tbDhOqWqnC/taOF7HTBLeHbw33hQ8IB7TBVSs=" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=debug msg="completed challenge" Dec 09 05:54:28 gbvpi-bedroom go-librespot[8725]: time="2025-12-09T05:54:28-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:28 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:28 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:29 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:29 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:30 gbvpi-bedroom volumio[8163]: info: Discovery: A device disappeared from network Dec 09 05:54:30 gbvpi-bedroom volumio[8163]: info: Discovery: Device northpi-soundstation disappeared from network Dec 09 05:54:31 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 357. Dec 09 05:54:31 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:31 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:31 gbvpi-bedroom go-librespot[8749]: go-librespot daemon starting... Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="app state loaded" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:31 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:54:31 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:54:31 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 09 05:54:31 gbvpi-bedroom volumio-remote-updater[752]: Test mode enabled Dec 09 05:54:31 gbvpi-bedroom volumio-remote-updater[752]: Alpha mode disabled Dec 09 05:54:31 gbvpi-bedroom volumio-remote-updater[752]: Alpha legacy test mode disabled Dec 09 05:54:31 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=info msg="zeroconf server listening on port 38399" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="obtained new client token: AAAW/d6LLiaAixhRQzdCsuc1TYN/UUKTiiNoqlOHULx8cM+fqNn6qvBoKsVMC1bsH01X2FCsZv5EHYLnkii3ekIug7YX0QHI4fMWnnf2YNcoHB+wcAEeWnwMyM/R+nYNOPTBnTMhNwGqg1fCq40DQPWt/j2TaWUvnbrYW/407/GeyuoiR9lWUksHaEBn7Otticj0K4PsGlzCQB62hF/lTWC6n05zrQTNzPmwPr8QOpwqgIxG+SB0IBj5hA==" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:31 gbvpi-bedroom volumio[8163]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Dec 09 05:54:31 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:31 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:31-05:00" level=debug msg="completed challenge" Dec 09 05:54:32 gbvpi-bedroom go-librespot[8750]: time="2025-12-09T05:54:32-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:32 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:32 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetBrowseSources Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:32 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:33 gbvpi-bedroom volumio[8163]: info: BOOT COMPLETED Dec 09 05:54:33 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:33 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:34 gbvpi-bedroom volumio[8163]: info: Discovery: adding 357de02c-99c5-4ddd-be16-8ae369ed89c3 Dec 09 05:54:34 gbvpi-bedroom volumio[8163]: info: Discovery: Found device NorthPi-Soundstation Dec 09 05:54:34 gbvpi-bedroom volumio[8163]: info: Discovery: Connecting to remote: 192.168.1.28 Dec 09 05:54:35 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 358. Dec 09 05:54:35 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:35 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:35 gbvpi-bedroom go-librespot[8762]: go-librespot daemon starting... Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="app state loaded" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=info msg="zeroconf server listening on port 45929" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="obtained new client token: AACgSWfc1AI4CYT/UEf8eheGLg7DI9TqGrIpc8Q6c4y6t17p/xZRttIdVNClI4OsXeF8IsoM92b32mx22xXUUq9AAcrLBwYRtxiMRt4cFBQmrWVkZ76qcbl7BjO7nBAnc1tasK3nLvRS/eiJiHuGvrisxE2LynNmVFfsj6oS2mVA9/f4BYmZI2ien+Pd2OuV6tHlkEydZpG45zikF/yuwaWrlU0pHU9Ir9Aml/mtn8tj5VbzX4kF7IfHwQ==" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=debug msg="completed challenge" Dec 09 05:54:35 gbvpi-bedroom go-librespot[8763]: time="2025-12-09T05:54:35-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:35 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:35 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:35 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:35 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:38 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:38 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:38 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 359. Dec 09 05:54:38 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:38 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:38 gbvpi-bedroom go-librespot[8784]: go-librespot daemon starting... Dec 09 05:54:38 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:38-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:38 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:38-05:00" level=debug msg="app state loaded" Dec 09 05:54:38 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:38-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=info msg="zeroconf server listening on port 37037" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=debug msg="obtained new client token: AAApn5ot66p/uY+1uttVIoROTSkxUbZej7yxB6b7MEiqlDFh5iwqYzuxJoaS8YGcEtofPtbSvbrKCvOfg0o4erfVTsLrUDHS7YCQlwQlFuKSRpYfpMo0Xw7JeCAZ1RJNGWxpdxxd9O2gzh2a3TOpaq065K0yazQcwO0s8ClszeG4s5Cq/mBCG3KS7+phzVsWtb4egEjb1C1pWJE9j63bBNsBTzFuniaKAFYzDn1FJpCtAvnaC95B0xQ=" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=debug msg="completed challenge" Dec 09 05:54:39 gbvpi-bedroom go-librespot[8785]: time="2025-12-09T05:54:39-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:39 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:39 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:41 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:41 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:42 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 360. Dec 09 05:54:42 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:42 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:42 gbvpi-bedroom go-librespot[8793]: go-librespot daemon starting... Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=debug msg="app state loaded" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=info msg="zeroconf server listening on port 43369" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=debug msg="obtained new client token: AACrfVaSRNK6nqL9/ZsnDkxzaD3ZqC0f/66MIfOqsLf0MleBztbaqMSfAEB/q0ILPOBmyNU+im3/D2QvixZSpH6AdgDRFhzuw7qkZpQV17n3JwlyV1cfne/HfjTBwL3SM5dz6LQ2q9CxGdcjVaEEMzm8prWdxfUT6jM2zrcaNv0owbms3/BRKV0AYhUVubjeLcRsxnODWbnDE1ftn18RPf5Q6Qgtio0juYt5pwUKifT8HoJmyGQKsq1Jlw==" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54:42-05:00" level=debug msg="completed challenge" Dec 09 05:54:42 gbvpi-bedroom go-librespot[8794]: time="2025-12-09T05:54: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 " Dec 09 05:54:42 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:42 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:43 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:43 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:43 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:43 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:43 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:43 gbvpi-bedroom volumio[8163]: info: Listing playlists Dec 09 05:54:44 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:44 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:45 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 361. Dec 09 05:54:45 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:45 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:45 gbvpi-bedroom go-librespot[8804]: go-librespot daemon starting... Dec 09 05:54:45 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:45-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:45 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:45-05:00" level=debug msg="app state loaded" Dec 09 05:54:45 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:45-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=info msg="zeroconf server listening on port 36841" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=debug msg="obtained new client token: AAAT4I2KXpkq6HmKgJ+BsMuqEOLgLVKPpkN00zJtWP5raiacN1KE6q2iOUrFANjgpLTkkLwFvuGz6OjwSXPZIXYONBi4Lqjy7Yy7etkB6P9MDlfViSsiWtTuh8dmlmwo65k4mTBnXvX9uWkQabjBhUKZztHDQ0nF+lMS0eMbBm05pM5gI6JTBliJYJzmFclwsTwZzXo/ODF5ZkMTYTyutJ/EgBajQXwvkHICFN9zqV7oIJPd2tCP9KM=" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54:46-05:00" level=debug msg="completed challenge" Dec 09 05:54:46 gbvpi-bedroom go-librespot[8805]: time="2025-12-09T05:54: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 " Dec 09 05:54:46 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:46 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:47 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:47 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:49 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 362. Dec 09 05:54:49 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:49 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:49 gbvpi-bedroom go-librespot[8826]: go-librespot daemon starting... Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="app state loaded" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=info msg="zeroconf server listening on port 39993" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="obtained new client token: AADMckg+ABG28xFu/Tf+BLgrousTAXzGKycCgYiBwEANXX7GibJ8SceDTj7wycUsTYhEejO4ofmZpDPobdsFEd/PJ2QRzB/NxSopd/1PU0ND4D3ZymzCBHTDcaWgQrNce2FbpSDvKcgn2bpV0DvSTZbiMpZdSFdYU2bwdvwqh382rO6ixuKT4rrieEliVv5Pyr82ZAsyp9Zb4bbPW7xZJT0eZkmz0/C6ZKpfW4tA/9B5l62jCf/aA9I/GQ==" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="completed keyexchange" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=debug msg="completed challenge" Dec 09 05:54:49 gbvpi-bedroom go-librespot[8827]: time="2025-12-09T05:54:49-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:54:49 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:54:49 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:54:50 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:50 gbvpi-bedroom volumio[8163]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:54:52 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 363. Dec 09 05:54:52 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:52 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:54:52 gbvpi-bedroom go-librespot[8834]: go-librespot daemon starting... Dec 09 05:54:52 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:52-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:54:52 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:52-05:00" level=debug msg="app state loaded" Dec 09 05:54:52 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:52-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:54:53 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:53-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 05:54:53 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:53-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 05:54:53 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:53-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 05:54:53 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:53-05:00" level=info msg="zeroconf server listening on port 34187" Dec 09 05:54:53 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:53-05:00" level=debug msg="obtained new client token: AADNoTokN9H69uRqKgQWe7cwfiipfjAB3XmCXt1NT1ooXTj0M/36Y5r1Vmas8KJFHieAooQGqFoLbRn2wfPCvHSZjGtIX84QDT+r8GT+NbWTcNt5eCaJ6Owt7fBa2ePRaTufRoAGA5WgMWMy3P+I7QM5fi/U27nByZouU6yQuCgl+Xx6Dj+Zcu2JKiy+emORIpEKIw2P1Dc+th5+np0AmrfEIaAUWL/eg7AGV3k4o2JSXSE0wmbX8AY=" Dec 09 05:54:53 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:53-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:54:53 gbvpi-bedroom volumio[8163]: info: Initializing connection to go-librespot Websocket Dec 09 05:54:53 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:54:53-05:00" level=debug msg="new websocket client" Dec 09 05:54:53 gbvpi-bedroom volumio[8163]: info: Connection to go-librespot Websocket established Dec 09 05:54:53 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:53 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: info: Getting Spotify volume Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: SPOTIFY: SPOTIFY VOLUME undefined Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: SPOTIFY: VOLUMIO VOLUME 91 Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: info: Aligning Spotify Volume to Volumio Volume Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: info: CoreCommandRouter::volumioGetState Dec 09 05:54:56 gbvpi-bedroom volumio[8163]: info: Setting Spotify Volume from Volumio: 91 Dec 09 05:54:58 gbvpi-bedroom volumio[8163]: SPOTIFY: SETTING SPOTIFY VOLUME 91 Dec 09 05:54:58 gbvpi-bedroom volumio[8163]: info: Sending Spotify command with payload to local API: /player/volume Dec 09 05:55:00 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:55:00-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:00 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:55:00-05:00" level=debug msg="completed challenge" Dec 09 05:55:00 gbvpi-bedroom go-librespot[8835]: time="2025-12-09T05:55:00-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: Error: socket hang up Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: at connResetException (node:internal/errors:720:14) Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: at Socket.emit (node:events:526:35) Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: code: 'ECONNRESET', Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: response: undefined Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: } Dec 09 05:55:00 gbvpi-bedroom volumio[8163]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 05:55:00 gbvpi-bedroom sudo[8871]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 05:54' Dec 09 05:55:00 gbvpi-bedroom sudo[8871]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:00 gbvpi-bedroom sudo[8871]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:01 gbvpi-bedroom volumio-remote-updater[752]: [2025-12-09 05:55:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 09 05:55:01 gbvpi-bedroom volumio-remote-updater[752]: [2025-12-09 05:55:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 09 05:55:01 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:55:01.155 [8675.8675] INFO SampleApp: Socket closed Dec 09 05:55:01 gbvpi-bedroom vtcs[8699]: [2025-12-09 05:55:01.156] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Dec 09 05:55:01 gbvpi-bedroom systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:01 gbvpi-bedroom systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: volumio.service: Consumed 21.753s CPU time. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1071. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: volumio.service: Consumed 21.753s CPU time. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: Started volumio.service - Volumio Backend Module. Dec 09 05:55:01 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ------------------------------------------- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ----- Volumio3 ---- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ------------------------------------------- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ----- System startup ---- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ------------------------------------------- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: MYVOLUMIO Environment detected Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Plugin folders cleanup Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning into folder /volumio/app/plugins/ Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning category audio_interface Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning category miscellanea Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning category music_service Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning category plugins.json Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning category system_controller Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning category user_interface Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning into folder /data/plugins/ Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Scanning category music_service Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Plugin folders cleanup completed Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ------------------------------------------- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ----- Core plugins startup ---- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: ------------------------------------------- Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Loading plugins from folder /volumio/app/plugins/ Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Adding plugin upnp to MyMusic Plugins Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Loading plugins from folder /data/plugins/ Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Loading plugin "system"... Dec 09 05:55:02 gbvpi-bedroom volumio[8886]: info: Loading plugin "appearance"... Dec 09 05:55:03 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 364. Dec 09 05:55:03 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:03 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:03 gbvpi-bedroom go-librespot[8913]: go-librespot daemon starting... Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=debug msg="app state loaded" Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "network"... Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Refreshing Cached IP Addresses Dec 09 05:55:03 gbvpi-bedroom sudo[8921]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 05:55:03 gbvpi-bedroom sudo[8921]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:03 gbvpi-bedroom sudo[8921]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:03 gbvpi-bedroom sudo[8923]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 05:55:03 gbvpi-bedroom sudo[8923]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:03 gbvpi-bedroom sudo[8923]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "services"... Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "alsa_controller"... Dec 09 05:55:03 gbvpi-bedroom sudo[8936]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 09 05:55:03 gbvpi-bedroom sudo[8936]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "wizard"... Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "networkfs"... Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Starting Udev Watcher for removable devices Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Ignoring mount for partition: boot Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Ignoring mount for partition: volumio Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Ignoring mount for partition: volumio_data Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "volumio_command_line_client"... Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "upnp"... Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: [1765277703590] Starting Upmpd Daemon Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "my_music"... Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "mpd"... Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=info msg="zeroconf server listening on port 35795" Dec 09 05:55:03 gbvpi-bedroom volumio[8886]: info: Loading plugin "upnp_browser"... Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=debug msg="obtained new client token: AAAtIcNkMzUdzsQiX41HIw5T6mmQKIhAn0Sa9ev3PryC/DM0WPFyGbIZVqjvtF1uKA0GXUkpPVV6QStofIpJUC54158KAHsCqTl5OhuYas0Bjr28GCp3V86f4vVuCoAuf3YL7OjOkrqSDWJ9g0Cr8KMctp18hYRGIzaGNl13E6WnMW1SlwBW5Xxt5EDuoI/eS9KwyTJPjxSy4fi+kQ/np6aVc00beksusf3V063VncOq/4E+TBXPtq5nXQ==" Dec 09 05:55:03 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:04 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:04-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:04 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:04-05:00" level=debug msg="completed challenge" Dec 09 05:55:04 gbvpi-bedroom go-librespot[8914]: time="2025-12-09T05:55:04-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Starting UPNP Browser Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Loading plugin "alarm-clock"... Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Loading plugin "airplay_emulation"... Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Starting Shairport Sync Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Loading plugin "last_100"... Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Loading plugin "webradio"... Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Loading plugin "i2s_dacs"... Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: I2S DAC not set, start Auto-detection Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Loading plugin "volumiodiscovery"... Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: *** WARNING *** For more information see Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 05:55:04 gbvpi-bedroom node[8886]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: *** WARNING *** For more information see Dec 09 05:55:04 gbvpi-bedroom node[8886]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 05:55:04 gbvpi-bedroom node[8886]: *** WARNING *** For more information see Dec 09 05:55:04 gbvpi-bedroom node[8886]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 09 05:55:04 gbvpi-bedroom node[8886]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 09 05:55:04 gbvpi-bedroom node[8886]: *** WARNING *** For more information see Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Discovery: Started advertising with name: GBVPi-Bedroom Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 05:55:04 gbvpi-bedroom volumio[8886]: info: Loading plugin "jellyfin"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading plugin "spop"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading plugin "outputs"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading plugin "albumart"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Plugin example_plugin is not enabled Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading plugin "inputs"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading plugin "updater_comm"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Plugin mpdemulation is not enabled Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading plugin "rest_api"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading plugin "websocket"... Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Starting Socket.io Server version 1.7.4 Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Loading i18n strings for locale en Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: Updating browse sources language Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::initPlayerControls Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: Express server listening on port 3000 Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: [Metrics] WebUI: 3s 827.82ms Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::resetVolumioState Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::getcurrentVolume Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:05 gbvpi-bedroom volumio[8886]: info: Volumio Network Manager: Network status updated: 2 Dec 09 05:55:05 gbvpi-bedroom volumio[8962]: Forking 3 albumart workers Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: VolumeController:: Volume=91 Mute =false Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::pushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioPushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::updateTrackBlock Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrackBlock Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioRetrievevolume Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Reloading queue from file Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::setRepeat true single undefined Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::pushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioPushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::setRandom null Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::pushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioPushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Setting Device type: Raspberry PI Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: VolumeController:: Volume=91 Mute =false Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::pushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioPushState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Completed loading Core Plugins Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Preparing to generate the ALSA configuration file Dec 09 05:55:06 gbvpi-bedroom volumio-remote-updater[752]: [2025-12-09 05:55:06] [connect] Successful connection Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: adding 357de02c-99c5-4ddd-be16-8ae369ed89c3 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: Found device NorthPi-Soundstation Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: Connecting to remote: 192.168.1.28 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: adding 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: Found device GBVPi-Bedroom Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: this is already registered, 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: Found device GBVPi-Bedroom Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:06 gbvpi-bedroom volumio-remote-updater[752]: [2025-12-09 05:55:06] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765277706 101 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Asound.conf file written Dec 09 05:55:06 gbvpi-bedroom sudo[9020]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 09 05:55:06 gbvpi-bedroom sudo[9020]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:06 gbvpi-bedroom sudo[9020]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Output device has changed, restarting MPD Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Output device has changed, restarting Shairport Sync Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:06 gbvpi-bedroom sudo[9027]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 05:55:06 gbvpi-bedroom sudo[9027]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:06 gbvpi-bedroom sudo[9028]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 05:55:06 gbvpi-bedroom sudo[9028]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:06 gbvpi-bedroom sudo[9027]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: ___________ START PLUGINS ___________ Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: ControllerMpd::onStart: Initializing MPD Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Creating MPD Configuration file Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: [1765277706423] CoreMusicLibrary::Adding element Media Servers Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: UPNP Browser: Client initialized successfully Dec 09 05:55:06 gbvpi-bedroom sudo[9038]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 05:55:06 gbvpi-bedroom sudo[9038]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:06 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.277s CPU time. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 05:55:06 gbvpi-bedroom sudo[9036]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:06 gbvpi-bedroom sudo[9036]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:06 gbvpi-bedroom sudo[9036]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: [1765277706523] CoreMusicLibrary::Adding element Last_100 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: [1765277706526] CoreMusicLibrary::Adding element Webradio Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Initializing BBC Radios Dec 09 05:55:06 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 05:55:06 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Discovery: Getting this device information Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: [1765277706666] CoreMusicLibrary::Adding element Jellyfin Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: Cannot find translation for source Jellyfin Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: [jellyfin] Initialized plugin with device info: {"host":"http://192.168.1.97","id":"74ce6260-2045-48bb-acbd-0b75ccb5d93e","name":"GBVPi-Bedroom","serviceName":"Volumio","state":{"albumart":"https://jellyfin.lukeaurio.net/Items/2a8b0b42bfe09e9da6781f7cc9edae11/Images/Primary?maxWidth=500&maxHeight=500&quality=90","artist":"King Gizzard & The Lizard Wizard","mute":false,"status":"stop","track":"Mars For The Rich (Live at Red Rocks '22)","volume":91},"type":"device"} Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Creating Spotify config file Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:06 gbvpi-bedroom sudo[9057]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 05:55:06 gbvpi-bedroom sudo[9057]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 05:55:06 gbvpi-bedroom sudo[9057]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:06 gbvpi-bedroom volumio[8979]: Starting albumart workers Dec 09 05:55:06 gbvpi-bedroom volumio[8886]: info: Volumio Calling Home Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: MPD Permissions set Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: MPD Permissions set Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Spotify config file written Dec 09 05:55:07 gbvpi-bedroom volumio[8980]: Starting albumart workers Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 09 05:55:07 gbvpi-bedroom sudo[9072]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 09 05:55:07 gbvpi-bedroom sudo[9072]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:07 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:07 gbvpi-bedroom go-librespot[9081]: go-librespot daemon starting... Dec 09 05:55:07 gbvpi-bedroom sudo[9072]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="app state loaded" Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:07 gbvpi-bedroom volumio[8978]: Starting albumart workers Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: No need to fix Spotify hosts Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Volumio called home Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Starting Shairport Sync Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Starting Shairport Sync Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Starting Shairport Sync Dec 09 05:55:07 gbvpi-bedroom sudo[9100]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:55:07 gbvpi-bedroom sudo[9100]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:07 gbvpi-bedroom sudo[9098]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:55:07 gbvpi-bedroom sudo[9098]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:07 gbvpi-bedroom sudo[9104]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:55:07 gbvpi-bedroom sudo[9104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:07 gbvpi-bedroom sudo[8936]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:07 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: [jellyfin-poller] Polled HTTPS://jellyfin.lukeaurio.net: online Dec 09 05:55:07 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 05:55:07 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:55:07 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.715s CPU time. Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=info msg="zeroconf server listening on port 45493" Dec 09 05:55:07 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:55:07 gbvpi-bedroom sudo[9098]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:07 gbvpi-bedroom sudo[9100]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:07 gbvpi-bedroom sudo[9104]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="obtained new client token: AABk1tWFbLZBAsWYIMn6WAKmEo+MvtjlxqDvOw72NxkYeJiOaRChyMG/UtwyOcdKUBUJc1hDS3N3w7zjceDnHkIy6BBfGxooohjC4epmoH62xw1c/EObVvKz0NZchXobbqJPPM4TLP31VsYT2Kk8pBGUyBpCqxEjztPREZLDrVKpktA53cLsUrA43DjOkYBR5ZB9y45epzJF8T/5Jd9PKkSDktgwxO14SrGieokPv7UDE+WIFWwafS+Qsg==" Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Shairport-Sync Started Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: Error adding Membership: Error: addMembership EINVAL Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Shairport-Sync Started Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: Shairport-Sync Started Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:07 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:07-05:00" level=debug msg="completed challenge" Dec 09 05:55:07 gbvpi-bedroom volumio[8886]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 09 05:55:08 gbvpi-bedroom go-librespot[9085]: time="2025-12-09T05:55:08-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:08 gbvpi-bedroom mpd[9067]: 2025-12-09T05:55:08 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 09 05:55:08 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 09 05:55:08 gbvpi-bedroom sudo[9038]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:08 gbvpi-bedroom sudo[9028]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: Completed starting Core Plugins Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: ------------------------------------------- Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: ----- MyVolumio plugins startup ---- Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: ------------------------------------------- Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: error: MPD error: The expression evaluated to a falsy value: Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: assert.ok(self.idling) Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: error: The expression evaluated to a falsy value: Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: assert.ok(self.idling) Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: info: MPD running with PID9067 Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: ,establishing connection Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: error: updateQueue error: null Dec 09 05:55:08 gbvpi-bedroom volumio[8886]: error: updateQueue error: null Dec 09 05:55:10 gbvpi-bedroom volumio[8886]: info: go-librespot daemon successfully initialized Dec 09 05:55:11 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 365. Dec 09 05:55:11 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:11 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:11 gbvpi-bedroom go-librespot[9139]: go-librespot daemon starting... Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="app state loaded" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=info msg="zeroconf server listening on port 41285" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="obtained new client token: AACC4jsuE2rH7F2pmg2qeljTL+v7VWbbzADT1qp1r4feKmFh+ec7a0qulUG8OfsdFZs3L+uW9lVEZ2nDhq4RTqy6PZunQ19NMIlIuGh5tkzTEF1wPwCUk3KlUcmr7wFC8NOiMpKsstn0lzRFwg9/Vtc3Nzs1jltk/tGv5LzLNNyFCPmt475o5bgZiIX5UpDZxBNcPGPMOaW8WNDddkV/1ItzZ0h/G1fHTktFmEcZW1FA1VNoIvQoT32tfA==" Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:11 gbvpi-bedroom sudo[9148]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 05:55:11 gbvpi-bedroom sudo[9148]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:11 gbvpi-bedroom sudo[9150]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 05:55:11 gbvpi-bedroom sudo[9150]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:11 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 09 05:55:11 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 09 05:55:11 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 09 05:55:11 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 09 05:55:11 gbvpi-bedroom mpd_monitor.sh[9153]: MPD Monitor Service: Starting MPD Monitor Service Dec 09 05:55:11 gbvpi-bedroom sudo[9150]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:11 gbvpi-bedroom sudo[9148]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=debug msg="completed challenge" Dec 09 05:55:11 gbvpi-bedroom volumio[8886]: info: Successfully started MPD Monitor Dec 09 05:55:11 gbvpi-bedroom volumio[8886]: info: Successfully started MPD Monitor Dec 09 05:55:11 gbvpi-bedroom go-librespot[9140]: time="2025-12-09T05:55:11-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:11 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:11 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:13 gbvpi-bedroom sudo[9172]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 09 05:55:13 gbvpi-bedroom sudo[9172]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:13 gbvpi-bedroom sudo[9172]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:13 gbvpi-bedroom sudo[9174]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 09 05:55:13 gbvpi-bedroom sudo[9174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:13 gbvpi-bedroom sudo[9177]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 09 05:55:13 gbvpi-bedroom sudo[9174]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:13 gbvpi-bedroom sudo[9177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:13 gbvpi-bedroom sudo[9177]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: info: Upmpdcli Daemon Started Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:13 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:15 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 366. Dec 09 05:55:15 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:15 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:15 gbvpi-bedroom go-librespot[9180]: go-librespot daemon starting... Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="app state loaded" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=info msg="zeroconf server listening on port 37507" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="obtained new client token: AADAEDsOXkY9sdjph6Uq8yJnQ7/xMO+YNWHw3f+T2YaA83Ys8t1dCC9AAG9GS1oVY3r/8naau2FXgUCB4vUHTkv9uGdJzMe/iiXuecDowPMNU73AgKYvDFRbyjhKncUhQXhmvn2MM5PwCz7Iairz8YVa6Y++yq+J8HAgUl1DOFbKYX+lvreakfebuMjkcxKxN0Rut63GWHzLlF4hkkMbQJ83M+bwVt6CxVBEha+hmPwlraBqX2/MmtP4Xg==" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55:15-05:00" level=debug msg="completed challenge" Dec 09 05:55:15 gbvpi-bedroom go-librespot[9181]: time="2025-12-09T05:55: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 " Dec 09 05:55:15 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:15 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Adding plugin bluetooth to MyMusic Plugins Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Adding plugin multiroom to MyMusic Plugins Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Adding plugin metavolumio to MyMusic Plugins Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Adding plugin cd_controller to MyMusic Plugins Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 09 05:55:16 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: Starting MyVolumio Remote Streaming Endpoints Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: MyVolumio login type: Token Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: Streaming services startup Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: Starting Streaming Daemon Dec 09 05:55:17 gbvpi-bedroom sudo[9189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 09 05:55:17 gbvpi-bedroom sudo[9189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 09 05:55:17 gbvpi-bedroom sudo[9189]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: error: Cannot start Volumio Streaming Daemon Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 09 05:55:17 gbvpi-bedroom volumio[8886]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MyVolumio token set successfully Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MYVOLUMIO: Adding device Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MYVOLUMIO: Evaluating Server Dec 09 05:55:18 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 367. Dec 09 05:55:18 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MyVolumio Plan changed: premium Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Removing browser output: myVolumio user plan is not superstar Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Removing audio output: Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MYVOLUMIO: Adding device Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MYVOLUMIO: Evaluating Server Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Remote config written successfully Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Starting Tunnel 1 Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Starting Tunnel Connection Checker Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Completed starting MyVolumio Plugin Dec 09 05:55:18 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:18 gbvpi-bedroom go-librespot[9215]: go-librespot daemon starting... Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=debug msg="app state loaded" Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=info msg="zeroconf server listening on port 38221" Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MYVolumio Device enabled Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: MyVolumio status changed Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Streaming services startup Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: Starting Streaming Daemon Dec 09 05:55:18 gbvpi-bedroom sudo[9242]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 09 05:55:18 gbvpi-bedroom sudo[9242]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 09 05:55:18 gbvpi-bedroom sudo[9242]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=debug msg="obtained new client token: AAAUVER0IwUDLrytCkS51FReaie4y9nK6fUE/8ZNuEsnx457WDrryO85fFPMknDeQRtEtROhhAwz/SliIJ6DZPaHgYvEYqJUjr3AcRy+02CuBlpx+arRIhXPCd/qZycvNvWBpypFPTgqy8Fd8CwAFXQymCK0QNq0svCJFbKXcqgSgsKElygaJnTpIe3il0JjgUBoUEasABK9Mznb09KwLI1gsgqxCtqOWKMnf0Qk5QFy6jVVAJgUdrsUNw==" Dec 09 05:55:18 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 09 05:55:18 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 09 05:55:19 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:19-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:19 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:19-05:00" level=debug msg="completed challenge" Dec 09 05:55:19 gbvpi-bedroom go-librespot[9216]: time="2025-12-09T05:55:19-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:19 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:19 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Dec 09 05:55:19 gbvpi-bedroom sudo[9246]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 09 05:55:19 gbvpi-bedroom sudo[9246]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:19 gbvpi-bedroom sudo[9246]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: MultiRoom plugin initialized Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: STOPPING SNAPCLIENT Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: Snap server stop Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: STOPPING volumioStreaming Dec 09 05:55:19 gbvpi-bedroom sudo[9264]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 09 05:55:19 gbvpi-bedroom sudo[9264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:19 gbvpi-bedroom sudo[9266]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 09 05:55:19 gbvpi-bedroom sudo[9266]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 09 05:55:19 gbvpi-bedroom sudo[9268]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 09 05:55:19 gbvpi-bedroom sudo[9268]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:19 gbvpi-bedroom sudo[9271]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 09 05:55:19 gbvpi-bedroom sudo[9271]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:19 gbvpi-bedroom sudo[9271]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 09 05:55:19 gbvpi-bedroom sudo[9264]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:19 gbvpi-bedroom sudo[9266]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 09 05:55:19 gbvpi-bedroom sudo[9268]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: Preparing to generate the ALSA configuration file Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: Reading ALSA contributions from plugins. Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: Removed streaming files Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: volumioStreaming STOPPED Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: SNAPSERVER STOPPED Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: MRS: SNAPCLIENT STOPPED Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: error: Cannot start Volumio Streaming Daemon Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 09 05:55:19 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Asound.conf file written Dec 09 05:55:20 gbvpi-bedroom sudo[9278]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 09 05:55:20 gbvpi-bedroom sudo[9278]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:20 gbvpi-bedroom sudo[9278]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Output device has changed, restarting MPD Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Output device has changed, restarting Shairport Sync Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:20 gbvpi-bedroom sudo[9284]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 09 05:55:20 gbvpi-bedroom sudo[9284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:20 gbvpi-bedroom sudo[9284]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 09 05:55:20 gbvpi-bedroom sudo[9288]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:20 gbvpi-bedroom sudo[9288]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: [FUNC] onStart Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: MRS: Pushing multiroomSync output for this device Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: MRS: Pushing multiroomSync output Dec 09 05:55:20 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding audio output: Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding audio output: Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:20 gbvpi-bedroom bluetoothd[732]: Path / reserved for Adv Monitor app :1.17100 Dec 09 05:55:20 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 09 05:55:20 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 09 05:55:20 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.842s CPU time. Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding METAVOLUMIO REST API Endpoints Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:55:20 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 09 05:55:20 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 09 05:55:20 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Preparing CD Folders Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding CD REST API Endpoints Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Starting UDEV Watcher for CD Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: Detecting CD presence with UDEV Dec 09 05:55:20 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 09 05:55:20 gbvpi-bedroom bluetoothd[732]: Adv Monitor app :1.17100 disconnected from D-Bus Dec 09 05:55:20 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 09 05:55:20 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 09 05:55:20 gbvpi-bedroom sudo[9304]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 09 05:55:20 gbvpi-bedroom sudo[9304]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 09 05:55:20 gbvpi-bedroom sudo[9304]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:21 gbvpi-bedroom mpd[9306]: 2025-12-09T05:55:21 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 09 05:55:21 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 09 05:55:21 gbvpi-bedroom sudo[9288]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 368. Dec 09 05:55:22 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:22 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:22 gbvpi-bedroom go-librespot[9309]: go-librespot daemon starting... Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="app state loaded" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=info msg="zeroconf server listening on port 40033" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="obtained new client token: AABxm9WBgJwogtZbKIsSGOdITJJ/nV3Eots4M2iNui3erJj+VgGW4MCiHTMkM3bct8VzcLtDUV4JhVEVdwPR62rpDQ7EPGEzZnOhIyOY4GQoFp7UKbo7OmABAluULVm3FpyndWDaHPLzD0BISw3I3yTGSkRlOJGgTMrC6cGCSoKvjMcGuqlsZp+VwbV8SnoYkjvVgeLCwVKGonq/DCjmkGj6eD57yvclDLsX5F9H+dQvqx5shCU0IF7/1g==" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=debug msg="completed challenge" Dec 09 05:55:22 gbvpi-bedroom go-librespot[9310]: time="2025-12-09T05:55:22-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding inputs REST Endpoints Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Scanning Audio Inputs Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Checking against Known Cards name Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding Server instance for streaming Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: error: Hi Res Audio Failed Login: Missing Login Data Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Dec 09 05:55:25 gbvpi-bedroom sudo[9336]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: QobuzConnect: Starting Qobuz Connect socket and service Dec 09 05:55:25 gbvpi-bedroom sudo[9336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding TIDAL REST API Endpoints Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Stopping AccessToken refresher cron for QOBUZ Dec 09 05:55:25 gbvpi-bedroom sudo[9343]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 09 05:55:25 gbvpi-bedroom sudo[9343]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 09 05:55:25 gbvpi-bedroom systemd[1]: vtcs.service: Killing process 8713 (vtcs) with signal SIGKILL. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: vtcs.service: Deactivated successfully. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 09 05:55:25 gbvpi-bedroom sudo[9336]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: AccessToken refresher cron started for QOBUZ Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding QOBUZ REST API Endpoints Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: MRS: Getting audio outputs on start Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: MRS: Requesting all other devices output Dec 09 05:55:25 gbvpi-bedroom sudo[9343]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:25 gbvpi-bedroom sudo[9346]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 09 05:55:25 gbvpi-bedroom sudo[9346]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Setting Geolocation for MyVolumio to us1 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Setting Geolocation for MyVolumio to us4 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:25 gbvpi-bedroom qobuz-connect[8675]: 20251209 05:55:25.406 [8675.8675] INFO SampleApp: Stopping Local configuration server Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: MPD Permissions set Dec 09 05:55:25 gbvpi-bedroom sudo[9349]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Dec 09 05:55:25 gbvpi-bedroom sudo[9349]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom sudo[9349]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: error: updateQueue error: null Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioStop Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::stop Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 09 05:55:25 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 369. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Starting Shairport Sync Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: MRS: Found cast device: Google-Home-Mini-f209fa314cb426d40a59bcf66354ddc9 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding audio output: Dec 09 05:55:25 gbvpi-bedroom sudo[9365]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 09 05:55:25 gbvpi-bedroom sudo[9365]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: MRS: Found cast device: SmartTV-4K-fe72c264393a59c76d38e27b8168114d Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Adding audio output: Dec 09 05:55:25 gbvpi-bedroom sudo[9367]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 09 05:55:25 gbvpi-bedroom sudo[9367]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:25 gbvpi-bedroom go-librespot[9364]: go-librespot daemon starting... Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=debug msg="app state loaded" Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 09 05:55:25 gbvpi-bedroom autossh[8656]: received signal to exit (15) Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Dec 09 05:55:25 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.565s CPU time. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: sshtunnel.service: Deactivated successfully. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 09 05:55:25 gbvpi-bedroom sudo[9367]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Shairport-Sync Started Dec 09 05:55:25 gbvpi-bedroom systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 09 05:55:25 gbvpi-bedroom sudo[9365]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Remote SSH Started Dec 09 05:55:25 gbvpi-bedroom autossh[9379]: port set to 0, monitoring disabled Dec 09 05:55:25 gbvpi-bedroom autossh[9379]: starting ssh (count 1) Dec 09 05:55:25 gbvpi-bedroom autossh[9379]: ssh child pid is 9382 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Successfully Added MyVolumio device Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: Successfully Added MyVolumio device Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:25 gbvpi-bedroom volumio[8886]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=info msg="zeroconf server listening on port 43759" Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=debug msg="obtained new client token: AADAUq2bqdSyOYiQ2Y4E19wknCcgY0IN3NTWxa6wdEPW4GgUZhVaZmz5Garqq6O7ZJxK6Hz1Tb/IFVqoK7t90qs5c/UW0CXFrXDUAdr0kU13+iSh7nRyzevOzkYIL1GVFDELUqLbFWC3/cFrl+ObOD2g4UHvDFbqsw6fAabS0Zeffng1vLyPf09tPpYENBpg2/IzgIAzGAkCYqPSSlM0AKQS79genaHP0Ay1MaURJUtmCUrS9W83UnLERA==" Dec 09 05:55:25 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:25-05:00" level=warning msg="failed to connect to AP ap-gue1.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.255.62:4070: connect: connection refused" Dec 09 05:55:26 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:26-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" Dec 09 05:55:26 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:80" Dec 09 05:55:26 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:26-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:26 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:26-05:00" level=debug msg="completed challenge" Dec 09 05:55:26 gbvpi-bedroom volumiossh-tunnel[9382]: Warning: Permanently added '[eu1.myvolumio.org]:2222' (RSA) to the list of known hosts. Dec 09 05:55:26 gbvpi-bedroom go-librespot[9370]: time="2025-12-09T05:55:26-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:26 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:26 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:26 gbvpi-bedroom systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 09 05:55:26 gbvpi-bedroom systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 09 05:55:26 gbvpi-bedroom systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 09 05:55:26 gbvpi-bedroom sudo[9346]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: Executing endpoint qc_getconfig Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.350 [9397.9397] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.353 [9397.9397] INFO VolumeManager: [0x1d4c588]: Setting new playback volume: 75 Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.354 [9397.9397] INFO VolumeManager: [0x1d4c588]: Setting new mute state: 0 Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.354 [9397.9397] INFO QobuzConnect: [0x1d4cf58]: Client initialized! Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.354 [9397.9397] INFO SampleApp: Starting Avahi advertising, name: GBVPi-Bedroom, service name: _qobuz-connect._tcp Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.367 [9397.9397] INFO LocalConfigManager: [0x1d4be68]: Starting Local Configuration server Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.367 [9397.9397] INFO SampleApp: Starting Local configuration server Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.367 [9397.9397] INFO SampleApp: Connected to UNIX socket client 0x1d36818 Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: Updating MyVolumio device info Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: Updating MyVolumio device info Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:26 gbvpi-bedroom qobuz-connect[9397]: 20251209 05:55:26.500 [9397.9397] INFO SampleApp: Playback volume changed: 75 Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: Successfully Updated MyVolumio device Dec 09 05:55:26 gbvpi-bedroom volumio[8886]: info: Successfully Updated MyVolumio device Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: TidalConnect service stoped! Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 09 05:55:28 gbvpi-bedroom sudo[9412]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 09 05:55:28 gbvpi-bedroom sudo[9412]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:28 gbvpi-bedroom sudo[9416]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 09 05:55:28 gbvpi-bedroom sudo[9416]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:28 gbvpi-bedroom systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:28 gbvpi-bedroom sudo[9412]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:28 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 09 05:55:28 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 09 05:55:28 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 09 05:55:28 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 09 05:55:28 gbvpi-bedroom mpd_monitor.sh[9420]: MPD Monitor Service: Starting MPD Monitor Service Dec 09 05:55:28 gbvpi-bedroom sudo[9416]: pam_unix(sudo:session): session closed for user root Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Successfully started MPD Monitor Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Executing endpoint tc_getconfig Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 09 05:55:28 gbvpi-bedroom vtcs[9418]: STARTING TidalConnect services, version: 1.5.2.56 Dec 09 05:55:28 gbvpi-bedroom vtcs[9418]: STARTED TidalConnect services. Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Executing endpoint tc_connect Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Connecting to TidalConnect Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::servicePushState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::pushState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioPushState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: MRS: Pushing multiroomSync output update for this device Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: MRS: Pushing multiroomSync output Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::servicePushState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreStateMachine::pushState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioPushState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: MRS: Pushing multiroomSync output update for this device Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: MRS: Pushing multiroomSync output Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: CorePlayQueue::getTrack 0 Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 09 05:55:28 gbvpi-bedroom volumio[8886]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 09 05:55:29 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 370. Dec 09 05:55:29 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:29 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:29 gbvpi-bedroom go-librespot[9438]: go-librespot daemon starting... Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=debug msg="app state loaded" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55: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]" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55: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]" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55: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]" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=info msg="zeroconf server listening on port 36127" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=debug msg="obtained new client token: AAD/HFWfuFomt4r9oR5YS0hLwHfcYNsSnucuT9k4+Zv2hYo45sGaYVTa4MNPwvLf5nCy03Jma3P2S6UK5KIG8nrksI5WzMst7GDm2L0WyKnWCHJGqdGcMAvQh+1AjNoaMFUgv1HYMVi6CsxQDkuyln8cE0P9TNHQUY9S7gCAXa6MV7+Q03J7sKbqK7ItIA4RnMCOfmKN/Vw8JqjSQ0EiW+MQiBp39SVIFksDHncNzl4IpNszfO7A5rXyuA==" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=debug msg="completed challenge" Dec 09 05:55:29 gbvpi-bedroom go-librespot[9439]: time="2025-12-09T05:55:29-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:29 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:29 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: TidalConnect service started! Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: [Metrics] CommandRouter: 29s 135.42ms Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumiosetStartupVolume Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::Close All Modals sent Dec 09 05:55:31 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::Close All Modals sent Dec 09 05:55:32 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 09 05:55:32 gbvpi-bedroom volumio[8886]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Dec 09 05:55:32 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:32 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 09 05:55:32 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 09 05:55:32 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 09 05:55:32 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 371. Dec 09 05:55:32 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:32 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:32 gbvpi-bedroom go-librespot[9449]: go-librespot daemon starting... Dec 09 05:55:32 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:32-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:32 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:32-05:00" level=debug msg="app state loaded" Dec 09 05:55:32 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:32-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=info msg="zeroconf server listening on port 46371" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=debug msg="obtained new client token: AADfE+DfUZF3MQOXUCbHEAuDP57N0C8Pz5xy47Zm+pHybh/licNIE8yA8nMMe9rEE3Bb5fUFFyjRGa6CxajueLw1Pr7YfF5KGFvJXOVZ8n4sTb3Es2LJYAvwKDIYTm4gCf3Yllf8WKKW3Sp6cnwbJPlBTGNuw9N+AVc62gFZ+olF1V+p7cAcLSMUR3Cw42X6N2IerCB4rXV3hkYls9D1Q2BVJkJxgkdlOPsNnm0aYANOBAqni35OhcY=" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=debug msg="completed challenge" Dec 09 05:55:33 gbvpi-bedroom go-librespot[9450]: time="2025-12-09T05:55:33-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:33 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:33 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:33 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:33 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:34 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:34 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:34 gbvpi-bedroom volumio[8886]: info: Discovery: A device disappeared from network Dec 09 05:55:34 gbvpi-bedroom volumio[8886]: info: Discovery: Device northpi-soundstation disappeared from network Dec 09 05:55:36 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 372. Dec 09 05:55:36 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:36 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:36 gbvpi-bedroom go-librespot[9471]: go-librespot daemon starting... Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="app state loaded" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=info msg="zeroconf server listening on port 35827" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="obtained new client token: AADk82jItEXvA1GaaPzatIg0GayDOTaCQjOL4olhVL8mU3XM4roUSXY/OcmlkIbIP1fayUHt45z0G76h7rlPDGrt9MDr0kCNIopqkZnuoYvsLpLt6iRXou/4QVkXJA6fSqgvcU7F6/PhNN1Ge8C1FuKmc6b/GbMWsFhPd1SM80OeKJPP48ymuAqc93M3iK0Nu1EmChccybq32XU+lPQlO0cjDEN+BedqJfSgnjGOHdwlNE806qNtsLwibA==" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=debug msg="completed challenge" Dec 09 05:55:36 gbvpi-bedroom go-librespot[9472]: time="2025-12-09T05:55:36-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:36 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:36 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:36 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:55:36 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 09 05:55:36 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 09 05:55:36 gbvpi-bedroom volumio-remote-updater[752]: Test mode enabled Dec 09 05:55:36 gbvpi-bedroom volumio-remote-updater[752]: Alpha mode disabled Dec 09 05:55:36 gbvpi-bedroom volumio-remote-updater[752]: Alpha legacy test mode disabled Dec 09 05:55:36 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetBrowseSources Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:37 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:38 gbvpi-bedroom volumio[8886]: info: Discovery: adding 357de02c-99c5-4ddd-be16-8ae369ed89c3 Dec 09 05:55:38 gbvpi-bedroom volumio[8886]: info: Discovery: Found device NorthPi-Soundstation Dec 09 05:55:38 gbvpi-bedroom volumio[8886]: info: Discovery: Connecting to remote: 192.168.1.28 Dec 09 05:55:38 gbvpi-bedroom volumio[8886]: info: BOOT COMPLETED Dec 09 05:55:39 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 373. Dec 09 05:55:39 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:39 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:39 gbvpi-bedroom go-librespot[9485]: go-librespot daemon starting... Dec 09 05:55:39 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:39-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:39 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:39-05:00" level=debug msg="app state loaded" Dec 09 05:55:39 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:39-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=info msg="zeroconf server listening on port 39425" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=debug msg="obtained new client token: AABRHBOZJ9nRa6cMqI0oxjb6uV8na12mzWBbr3wHAeV4pA16XKlOTe8Gtd55CIz2A65kfGGB4bfOZmCXSeEC5p8OeWTEbEIbV6+faY5PdOSHaQLF92SYk2yjwDt46BMp83RqbjsxLUktMvzy7okfcEx1+vRGHF6m8YYcV0RtD6AvTicak4G0V/IBNGvUqMVcwOk5SFSds9UeszlqpeHUo9Q3XituELTLtZjm8UlhMe5uRLIP5apvoh8=" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=debug msg="completed challenge" Dec 09 05:55:40 gbvpi-bedroom go-librespot[9486]: time="2025-12-09T05:55:40-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:40 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:40 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:40 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:40 gbvpi-bedroom volumio[8886]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 374. Dec 09 05:55:43 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:43 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:43 gbvpi-bedroom go-librespot[9494]: go-librespot daemon starting... Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="app state loaded" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: Initializing connection to go-librespot Websocket Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="new websocket client" Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: Connection to go-librespot Websocket established Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=info msg="zeroconf server listening on port 45423" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="obtained new client token: AACp5qvTSOzGcSC4DkXHO4m82aTkJo4/2JQlXxtFRx7LoLUd/0MwCY0kxrx4ZCOx6KSg14cZj0tsQSZxHVsQNPIZ9o0AWv+jbMzy5grPRhyWbhsVm6aieErVSCCnFnoQsZEv/7H7XC6NvJAmKrgXa/cOHHuDOOrF589PyzIS9m8D71IURQAcoOG1hORMgetWu8I3Watco79NYS9gQi1WEJfdYxaTKCu4NdM+e8rYYW0LYornWbECIwQEfQ==" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="completed keyexchange" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=debug msg="completed challenge" Dec 09 05:55:43 gbvpi-bedroom go-librespot[9495]: time="2025-12-09T05:55:43-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 09 05:55:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 09 05:55:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: Connection to go-librespot Websocket closed Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: CoreCommandRouter::volumioGetState Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:43 gbvpi-bedroom volumio[8886]: info: Listing playlists Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: info: Getting Spotify volume Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: errno: -111, Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: code: 'ECONNREFUSED', Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: syscall: 'connect', Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: address: '127.0.0.1', Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: port: 9879, Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: response: undefined Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: } Dec 09 05:55:46 gbvpi-bedroom volumio[8886]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 09 05:55:46 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 375. Dec 09 05:55:46 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:46 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 09 05:55:46 gbvpi-bedroom go-librespot[9528]: go-librespot daemon starting... Dec 09 05:55:46 gbvpi-bedroom go-librespot[9529]: time="2025-12-09T05:55:46-05:00" level=info msg="running go-librespot 0.4.0" Dec 09 05:55:46 gbvpi-bedroom go-librespot[9529]: time="2025-12-09T05:55:46-05:00" level=debug msg="app state loaded" Dec 09 05:55:46 gbvpi-bedroom go-librespot[9529]: time="2025-12-09T05:55:46-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 09 05:55:46 gbvpi-bedroom sudo[9537]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-09 05:54' Dec 09 05:55:46 gbvpi-bedroom sudo[9537]: 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"