Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:00 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 129. Dec 06 03:38:00 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:00 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:00 gbvpi-bedroom go-librespot[12080]: go-librespot daemon starting... Dec 06 03:38:00 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:00-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:00 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:00-05:00" level=debug msg="app state loaded" Dec 06 03:38:00 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:00-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=info msg="zeroconf server listening on port 42763" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=debug msg="obtained new client token: AADnfZVdshvGOSnQxL+aewifnYqWxulOGUSliWgs7aJpRudxHm3cmVexsqz3lCQ9ft3doqB/U7vVl1pSx7ksnV2lqCw4zMKZHWWEuLLVh7Qjj7bq+OxC89FNde2/GLqCuHwzb68c+4Qx2lSg+uBWP+7C60kaYv1IfFZb+xqnDbM+TMT9lUOsmDuixw28OI/qJtVivr8ynlGp55l2D2CvbJjOp4V+DJLzYbAakuRwpxtl9qvTFw0kAnk=" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-05:00" level=debug msg="completed challenge" Dec 06 03:38:01 gbvpi-bedroom go-librespot[12081]: time="2025-12-06T03:38:01-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 06 03:38:01 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:01 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Adding plugin bluetooth to MyMusic Plugins Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Adding plugin multiroom to MyMusic Plugins Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Adding plugin metavolumio to MyMusic Plugins Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Adding plugin cd_controller to MyMusic Plugins Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 06 03:38:02 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: Starting MyVolumio Remote Streaming Endpoints Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: MyVolumio login type: Token Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: Streaming services startup Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: Starting Streaming Daemon Dec 06 03:38:03 gbvpi-bedroom sudo[12089]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 03:38:03 gbvpi-bedroom sudo[12089]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 06 03:38:03 gbvpi-bedroom sudo[12089]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: error: Cannot start Volumio Streaming Daemon Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 03:38:03 gbvpi-bedroom volumio[11790]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 06 03:38:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 130. Dec 06 03:38:04 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:04 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:04 gbvpi-bedroom go-librespot[12095]: go-librespot daemon starting... Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=debug msg="app state loaded" Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MyVolumio token set successfully Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MYVOLUMIO: Adding device Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MYVOLUMIO: Evaluating Server Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-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 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-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 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-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 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=info msg="zeroconf server listening on port 34985" Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MyVolumio Plan changed: premium Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Removing browser output: myVolumio user plan is not superstar Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Removing audio output: Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MYVOLUMIO: Adding device Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MYVOLUMIO: Evaluating Server Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Remote config written successfully Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Starting Tunnel 1 Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Starting Tunnel Connection Checker Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=debug msg="obtained new client token: AAC7HzKYlRNTkFqk7IffjV4fXjoTfBCEd/N0cLvPHWYaQQYrj76Wcs3bZZcyld6q/ez2cL9mTzhgVE8fzEfSHrLAwlPXxdxQmin3fHWeo5/eINC/61Kvy1uklzimj9KwOqR3BwNS88rdZzf3OiOcG4SKNaAhldz5kjVrC1yUzZvT/WyleAJHroJPSe54lylzJOW5lMeR2OR3CbASnhxcfAU8U0VuB9HSxKuJ/1PQWiaeFZpF62/+A3mNkA==" Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Completed starting MyVolumio Plugin Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38:04-05:00" level=debug msg="completed challenge" Dec 06 03:38:04 gbvpi-bedroom go-librespot[12096]: time="2025-12-06T03:38: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 06 03:38:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MYVolumio Device enabled Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: MyVolumio status changed Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Streaming services startup Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: Starting Streaming Daemon Dec 06 03:38:04 gbvpi-bedroom sudo[12142]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 03:38:04 gbvpi-bedroom sudo[12142]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 06 03:38:04 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 06 03:38:04 gbvpi-bedroom sudo[12142]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Dec 06 03:38:05 gbvpi-bedroom sudo[12147]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 06 03:38:05 gbvpi-bedroom sudo[12147]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:05 gbvpi-bedroom sudo[12147]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: MultiRoom plugin initialized Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: STOPPING SNAPCLIENT Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: Snap server stop Dec 06 03:38:05 gbvpi-bedroom sudo[12164]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 06 03:38:05 gbvpi-bedroom sudo[12164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: STOPPING volumioStreaming Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 06 03:38:05 gbvpi-bedroom sudo[12169]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 06 03:38:05 gbvpi-bedroom sudo[12169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:05 gbvpi-bedroom sudo[12167]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 06 03:38:05 gbvpi-bedroom sudo[12167]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:05 gbvpi-bedroom sudo[12171]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 06 03:38:05 gbvpi-bedroom sudo[12171]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:05 gbvpi-bedroom sudo[12171]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 06 03:38:05 gbvpi-bedroom sudo[12164]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 06 03:38:05 gbvpi-bedroom sudo[12169]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 06 03:38:05 gbvpi-bedroom sudo[12167]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: Preparing to generate the ALSA configuration file Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: Setting Geolocation for MyVolumio to us4 Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: Setting Geolocation for MyVolumio to us4 Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: Reading ALSA contributions from plugins. Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: Removed streaming files Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: volumioStreaming STOPPED Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: SNAPSERVER STOPPED Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: MRS: SNAPCLIENT STOPPED Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: error: Cannot start Volumio Streaming Daemon Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 03:38:05 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Asound.conf file written Dec 06 03:38:06 gbvpi-bedroom sudo[12177]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 06 03:38:06 gbvpi-bedroom sudo[12177]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:06 gbvpi-bedroom sudo[12177]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Output device has changed, restarting MPD Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Output device has changed, restarting Shairport Sync Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:06 gbvpi-bedroom sudo[12183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 03:38:06 gbvpi-bedroom sudo[12183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:06 gbvpi-bedroom sudo[12186]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 03:38:06 gbvpi-bedroom sudo[12186]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:06 gbvpi-bedroom sudo[12183]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: [FUNC] onStart Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: MRS: Pushing multiroomSync output for this device Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: MRS: Pushing multiroomSync output Dec 06 03:38:06 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding audio output: Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding audio output: Dec 06 03:38:06 gbvpi-bedroom bluetoothd[807]: Path / reserved for Adv Monitor app :1.16248 Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:06 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 06 03:38:06 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 03:38:06 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.895s CPU time. Dec 06 03:38:06 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 06 03:38:06 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 03:38:06 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding METAVOLUMIO REST API Endpoints Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Preparing CD Folders Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding CD REST API Endpoints Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Starting UDEV Watcher for CD Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: Detecting CD presence with UDEV Dec 06 03:38:06 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 06 03:38:06 gbvpi-bedroom bluetoothd[807]: Adv Monitor app :1.16248 disconnected from D-Bus Dec 06 03:38:06 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 03:38:06 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 03:38:06 gbvpi-bedroom sudo[12203]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 03:38:06 gbvpi-bedroom sudo[12203]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 03:38:06 gbvpi-bedroom sudo[12203]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:07 gbvpi-bedroom mpd[12205]: 2025-12-06T03:38:07 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 06 03:38:07 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 06 03:38:07 gbvpi-bedroom sudo[12186]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 131. Dec 06 03:38:08 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:08 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:08 gbvpi-bedroom go-librespot[12208]: go-librespot daemon starting... Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=debug msg="app state loaded" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-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 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-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 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=info msg="zeroconf server listening on port 46219" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=debug msg="obtained new client token: AABJzB9zHXg6RfRVWyVaolm5SpNeU2I6kgcu6jR8L58VXhXCpLPzQKwdn0Betmy79eZgEkEAg/zxCdfzrybNng506sfFXkFB2MSwfbQzhVgchKZtEO8e8bVhPTTaNkD1tZPEJ8HxKmMNABZ9B2hTyn3WU+FuI4TcpnQvPyzGIIS0/YO7Qz++8iyRgVmgtWATxhz6YWC04eE5nEI8QmKOUW7jNztjq4xs0hUdHhG7iRQlk/WcEPdi2UnJ3Q==" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38:08-05:00" level=debug msg="completed challenge" Dec 06 03:38:08 gbvpi-bedroom go-librespot[12209]: time="2025-12-06T03:38: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 06 03:38:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:08 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding inputs REST Endpoints Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Scanning Audio Inputs Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Checking against Known Cards name Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding Server instance for streaming Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: error: Hi Res Audio Failed Login: Missing Login Data Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: QobuzConnect: Starting Qobuz Connect socket and service Dec 06 03:38:11 gbvpi-bedroom sudo[12234]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 06 03:38:11 gbvpi-bedroom sudo[12234]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding TIDAL REST API Endpoints Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Stopping AccessToken refresher cron for QOBUZ Dec 06 03:38:11 gbvpi-bedroom sudo[12241]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 06 03:38:11 gbvpi-bedroom sudo[12241]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 06 03:38:11 gbvpi-bedroom systemd[1]: vtcs.service: Killing process 11666 (vtcs) with signal SIGKILL. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: vtcs.service: Deactivated successfully. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 06 03:38:11 gbvpi-bedroom sudo[12234]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: AccessToken refresher cron started for QOBUZ Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding QOBUZ REST API Endpoints Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Updating MyVolumio device info Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:11 gbvpi-bedroom sudo[12241]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Updating MyVolumio device info Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: MRS: Getting audio outputs on start Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: MRS: Requesting all other devices output Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:11 gbvpi-bedroom sudo[12244]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 06 03:38:11 gbvpi-bedroom sudo[12244]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 06 03:38:11 gbvpi-bedroom qobuz-connect[11627]: 20251206 03:38:11.361 [11627.11627] INFO SampleApp: Stopping Local configuration server Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Successfully Added MyVolumio device Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Successfully Added MyVolumio device Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: MPD Permissions set Dec 06 03:38:11 gbvpi-bedroom sudo[12247]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Dec 06 03:38:11 gbvpi-bedroom sudo[12247]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom sudo[12247]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: error: updateQueue error: null Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioStop Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreStateMachine::stop Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Starting Shairport Sync Dec 06 03:38:11 gbvpi-bedroom sudo[12262]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 06 03:38:11 gbvpi-bedroom sudo[12262]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: MRS: Found cast device: SmartTV-4K-fe72c264393a59c76d38e27b8168114d Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding audio output: Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: MRS: Found cast device: Google-Home-Mini-f209fa314cb426d40a59bcf66354ddc9 Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Adding audio output: Dec 06 03:38:11 gbvpi-bedroom sudo[12264]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 03:38:11 gbvpi-bedroom sudo[12264]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:11 gbvpi-bedroom autossh[11601]: received signal to exit (15) Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Dec 06 03:38:11 gbvpi-bedroom systemd[1]: sshtunnel.service: Deactivated successfully. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Successfully Updated MyVolumio device Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Successfully Updated MyVolumio device Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 06 03:38:11 gbvpi-bedroom sudo[12262]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Remote SSH Started Dec 06 03:38:11 gbvpi-bedroom autossh[12268]: port set to 0, monitoring disabled Dec 06 03:38:11 gbvpi-bedroom autossh[12268]: starting ssh (count 1) Dec 06 03:38:11 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 132. Dec 06 03:38:11 gbvpi-bedroom autossh[12268]: ssh child pid is 12271 Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 03:38:11 gbvpi-bedroom go-librespot[12272]: go-librespot daemon starting... Dec 06 03:38:11 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.629s CPU time. Dec 06 03:38:11 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:11 gbvpi-bedroom sudo[12264]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:11-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:11-05:00" level=debug msg="app state loaded" Dec 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:11-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:11 gbvpi-bedroom volumiossh-tunnel[12271]: Warning: Permanently added '[us4.myvolumio.org]:2222' (ED25519) to the list of known hosts. Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: info: Shairport-Sync Started Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: 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 06 03:38:11 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:11 gbvpi-bedroom volumio[11790]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38: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-gew1.spotify.com:80]" Dec 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:11-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 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:11-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 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:11-05:00" level=info msg="zeroconf server listening on port 40607" Dec 06 03:38:11 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:11-05:00" level=debug msg="obtained new client token: AABICk9aNZVePu6CDXXvJ+oJTzKCW0ggebzQ5qrQ3KLe1JfmFcnM6zDWtVUhln11S7Swtfuu1ykn2OAz42I7+DrIWKErLlFgu/tSKEdZzrG/igdqWtSWmCyFvipVD9LP+b3iaFO41A4by0/2dcJdtD5eJaEQYPChrY1X6YLVm6X1bM9cP/2pM7WS+mZUjRhMusJazepgph2aavLwuiAc8KGM9t5qtJ7aGSjmBIKVx9BhaWiM318htGiJUw==" Dec 06 03:38:12 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:12-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:12 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:12-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:12 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:12-05:00" level=debug msg="completed challenge" Dec 06 03:38:12 gbvpi-bedroom go-librespot[12273]: time="2025-12-06T03:38:12-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 06 03:38:12 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:12 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:13 gbvpi-bedroom systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 06 03:38:13 gbvpi-bedroom systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 06 03:38:13 gbvpi-bedroom systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 06 03:38:13 gbvpi-bedroom sudo[12244]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:13 gbvpi-bedroom volumio[11790]: info: Executing endpoint qc_getconfig Dec 06 03:38:13 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.390 [12295.12295] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 06 03:38:13 gbvpi-bedroom volumio[11790]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 06 03:38:13 gbvpi-bedroom volumio[11790]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.394 [12295.12295] INFO VolumeManager: [0x14b4588]: Setting new playback volume: 75 Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.395 [12295.12295] INFO VolumeManager: [0x14b4588]: Setting new mute state: 0 Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.395 [12295.12295] INFO QobuzConnect: [0x14b4f58]: Client initialized! Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.395 [12295.12295] INFO SampleApp: Starting Avahi advertising, name: GBVPi-Bedroom, service name: _qobuz-connect._tcp Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.404 [12295.12295] INFO LocalConfigManager: [0x14b3e68]: Starting Local Configuration server Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.404 [12295.12295] INFO SampleApp: Starting Local configuration server Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.404 [12295.12295] INFO SampleApp: Connected to UNIX socket client 0x149e818 Dec 06 03:38:13 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:13.540 [12295.12295] INFO SampleApp: Playback volume changed: 75 Dec 06 03:38:13 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: TidalConnect service stoped! Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 06 03:38:14 gbvpi-bedroom sudo[12310]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 06 03:38:14 gbvpi-bedroom sudo[12310]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:14 gbvpi-bedroom sudo[12314]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 03:38:14 gbvpi-bedroom sudo[12314]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:14 gbvpi-bedroom systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 06 03:38:14 gbvpi-bedroom sudo[12310]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:14 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 06 03:38:14 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 06 03:38:14 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 06 03:38:14 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 06 03:38:14 gbvpi-bedroom sudo[12314]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:14 gbvpi-bedroom mpd_monitor.sh[12318]: MPD Monitor Service: Starting MPD Monitor Service Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Successfully started MPD Monitor Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Executing endpoint tc_getconfig Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 06 03:38:14 gbvpi-bedroom vtcs[12316]: STARTING TidalConnect services, version: 1.5.2.56 Dec 06 03:38:14 gbvpi-bedroom vtcs[12316]: STARTED TidalConnect services. Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Executing endpoint tc_connect Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Connecting to TidalConnect Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::servicePushState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreStateMachine::pushState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioPushState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: MRS: Pushing multiroomSync output update for this device Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: MRS: Pushing multiroomSync output Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::servicePushState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreStateMachine::pushState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioPushState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: MRS: Pushing multiroomSync output update for this device Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: MRS: Pushing multiroomSync output Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 06 03:38:14 gbvpi-bedroom volumio[11790]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 06 03:38:15 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 133. Dec 06 03:38:15 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:15 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:15 gbvpi-bedroom go-librespot[12336]: go-librespot daemon starting... Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=debug msg="app state loaded" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-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 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-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 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=info msg="zeroconf server listening on port 35885" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=debug msg="obtained new client token: AADf9wrud3zED8V4+E/U/19SCvnCNhDtUYR3Is1OG+WJsRvpxWwX70xeekP3oLl37/j9I0J0MgcwaghKJVnCeF/vZolEk1dNtaX+hnMERnP9P5dcyx6Yegy9kYj/UiRmZDv8nJwjqFv1LldKIJn/edM1Ba6Ay+Z8cKDJG3j/2uuFhFW2YKnO3jeJGnZ3FtRfWb1HkRQXL10Usv4D/nb4mGsmWkhGZgbdM9/IFGGHKBxWu/e/J7cxFhKmzA==" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38:15-05:00" level=debug msg="completed challenge" Dec 06 03:38:15 gbvpi-bedroom go-librespot[12337]: time="2025-12-06T03:38: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 06 03:38:15 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:15 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: TidalConnect service started! Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: [Metrics] CommandRouter: 29s 305.58ms Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumiosetStartupVolume Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::Close All Modals sent Dec 06 03:38:17 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::Close All Modals sent Dec 06 03:38:18 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 06 03:38:18 gbvpi-bedroom volumio[11790]: 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 06 03:38:18 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:18 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 06 03:38:18 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 06 03:38:18 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 06 03:38:18 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 134. Dec 06 03:38:18 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:18 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:18 gbvpi-bedroom go-librespot[12347]: go-librespot daemon starting... Dec 06 03:38:18 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:18-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:18 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:18-05:00" level=debug msg="app state loaded" Dec 06 03:38:18 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:18-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-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 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-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 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-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 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-05:00" level=info msg="zeroconf server listening on port 36781" Dec 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-05:00" level=debug msg="obtained new client token: AABqaB6bgEVgXi94wLmNMPJVX1V626MethwL0Wa/SStwbkQTLqZz9ocCjPpJ/FcYKDiXZuE0VMwoPrZsnXAgrHvkMlvcE5UN8+JwQcmlMDrVBa25Cl8e+5ZvRv1egifNqzJ0epD7J5dTOAR3b02fzcTvaVDJFMg73J06Aj4ztlikyGPUL3tTzt2YcHFeGNkQkeWG/NSgCDRikJAXhUnX8pH29NPrPGg5mbLcHFxRNihLIds/9r7PRCs=" Dec 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38:19-05:00" level=debug msg="completed challenge" Dec 06 03:38:19 gbvpi-bedroom go-librespot[12348]: time="2025-12-06T03:38: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 06 03:38:19 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:19 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:20 gbvpi-bedroom volumio[11790]: info: Listing playlists Dec 06 03:38:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 135. Dec 06 03:38:22 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:22 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:22 gbvpi-bedroom go-librespot[12369]: go-librespot daemon starting... Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=debug msg="app state loaded" Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:22 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 03:38:22 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:22 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38: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 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38: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 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38: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 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=info msg="zeroconf server listening on port 36503" Dec 06 03:38:22 gbvpi-bedroom volumio-remote-updater[11354]: Test mode enabled Dec 06 03:38:22 gbvpi-bedroom volumio-remote-updater[11354]: Alpha mode disabled Dec 06 03:38:22 gbvpi-bedroom volumio-remote-updater[11354]: Alpha legacy test mode disabled Dec 06 03:38:22 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=debug msg="obtained new client token: AACKnwqF8piwE08eyKI2whgpImgeort2AxS8kRANEe+6I+6e7GeYPHRnVdqSoUFk153JgaBwKuLxMC+phqIQoQFWGYYUHPXMfK9vNzXA52han7yynTejgBn9zCtZXmzP3UeG6rsJLQaP6ibtNiE5ARt+vK7VZa5ex8KY9LOyJOw4ir+bC1Fw5HO4095aeLiNw9R6PdzGLSbwpZZMzQNKPhaJf7S8vyxdMVFG839YsMR5+luISxbdbWFN1Q==" Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38:22-05:00" level=debug msg="completed challenge" Dec 06 03:38:22 gbvpi-bedroom volumio[11790]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

ANNOUNCEMENT

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

FIX

\n
    \n
  • Nodejs 20.5.1 version pinning with static package fallback
    • \n
\n","title":"Update v4.073","updateavailable":true} Dec 06 03:38:22 gbvpi-bedroom go-librespot[12370]: time="2025-12-06T03:38: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 06 03:38:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:22 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:22 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetBrowseSources Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:23 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:24 gbvpi-bedroom volumio[11790]: info: BOOT COMPLETED Dec 06 03:38:25 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 136. Dec 06 03:38:25 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:25 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:25 gbvpi-bedroom go-librespot[12381]: go-librespot daemon starting... Dec 06 03:38:25 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:25-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:25 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:25-05:00" level=debug msg="app state loaded" Dec 06 03:38:25 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:25-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-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 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-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 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-05:00" level=info msg="zeroconf server listening on port 36407" Dec 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-05:00" level=debug msg="obtained new client token: AACnfRxcFa2abszxu5fnJ4McZyXmi4cCHZifZecf7f4jlhSS3JLfM1+oqj+7jZx9IBWUghNN2PMwvJ65mlqAzIC94uq9RHsadOyWMlzI+kyCuKGnPcn1hHYph2bxRULmKjSTU48rN9l8PzCR4fgbvasLxs1ndVOC0I6PpQ/ct500OBypY6mcu2ld4X37eP3FdSZzd6I/1REQGa24J7sJzad4bwPA20EE7z+1xy9XlsFkxtbAjmK1nAg=" Dec 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38:26-05:00" level=debug msg="completed challenge" Dec 06 03:38:26 gbvpi-bedroom go-librespot[12382]: time="2025-12-06T03:38: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 06 03:38:26 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:26 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:26 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:26 gbvpi-bedroom volumio[11790]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:29 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 137. Dec 06 03:38:29 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:29 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:29 gbvpi-bedroom go-librespot[12390]: go-librespot daemon starting... Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=debug msg="app state loaded" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:29 gbvpi-bedroom volumio[11790]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=debug msg="new websocket client" Dec 06 03:38:29 gbvpi-bedroom volumio[11790]: info: Connection to go-librespot Websocket established Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-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 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-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 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=info msg="zeroconf server listening on port 34491" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=debug msg="obtained new client token: AACuJoTaksYs4myAsTK5R5/TmbTyUgc3Kicx7weVQvBHYEM5VhY9oujt4KDGFdR9pvVWaMgOJj/dgI4CRvs2BcKWoBa2NQWjH+QbNxb1hFg4mx+qG4OvbNd8I3KCMv4kTkG4eUEVTyArBmB9GJIwmDPPsK8VDdc00Yr1VfZaDCfBJFz39xPsyw3/f0aDoSvLtos5AzIcCmBHmj2bAkBgh5k5jaLpoU1j/QZekqEKFGlSN/2O5WmqDGUVbA==" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38:29-05:00" level=debug msg="completed challenge" Dec 06 03:38:29 gbvpi-bedroom go-librespot[12405]: time="2025-12-06T03:38: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 06 03:38:29 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:29 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:29 gbvpi-bedroom volumio[11790]: info: Connection to go-librespot Websocket closed Dec 06 03:38:30 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:30 gbvpi-bedroom volumio[11790]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: info: Getting Spotify volume Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: errno: -111, Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: code: 'ECONNREFUSED', Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: syscall: 'connect', Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: address: '127.0.0.1', Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: port: 9879, Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: response: undefined Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: } Dec 06 03:38:32 gbvpi-bedroom volumio[11790]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 03:38:32 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 138. Dec 06 03:38:32 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:32 gbvpi-bedroom sudo[12427]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 03:37' Dec 06 03:38:32 gbvpi-bedroom sudo[12427]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:32 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:32 gbvpi-bedroom go-librespot[12425]: go-librespot daemon starting... Dec 06 03:38:32 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:32-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:32 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:32-05:00" level=debug msg="app state loaded" Dec 06 03:38:32 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:32-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:32 gbvpi-bedroom sudo[12427]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:33 gbvpi-bedroom volumio-remote-updater[11354]: [2025-12-06 03:38:33] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 06 03:38:33 gbvpi-bedroom volumio-remote-updater[11354]: [2025-12-06 03:38:33] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 06 03:38:33 gbvpi-bedroom vtcs[12316]: [2025-12-06 03:38:33.020] [tisoc] [error] [SpkconServer.cpp:375] recv error. socket disconnected Dec 06 03:38:33 gbvpi-bedroom systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:33 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:33.024 [12295.12295] INFO SampleApp: Socket closed Dec 06 03:38:33 gbvpi-bedroom systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 06 03:38:33 gbvpi-bedroom systemd[1]: volumio.service: Consumed 20.982s CPU time. Dec 06 03:38:33 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 03:38:33 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:33-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 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:33-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 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:33-05:00" level=info msg="zeroconf server listening on port 42967" Dec 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:33-05:00" level=debug msg="obtained new client token: AACHYlaQoT0Uk5oDpWcL+6S8mxdBimQ0mw3eoA9F1RKLb8R/k0Jkzj1wNah6+3WAwbcSCi+JJzrybelH171Q44yL+WNmmO3VKPZVHJ/FDSTeNNcibCu8u0aAv8zvr6SnaX8m2/bUWPmhcHhmhaaj5N+bUtTF/KfjKbbJzd6/nNJDLTkY7FQqcwJyaJKgP+9Uu1Gk269to3izTO3C9SVyD0xas2oyzBgfvgqrL/gIPgK0WAWEVDg3gu8=" Dec 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:33-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:33 gbvpi-bedroom systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1017. Dec 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:33-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38:33-05:00" level=debug msg="completed challenge" Dec 06 03:38:33 gbvpi-bedroom systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 06 03:38:33 gbvpi-bedroom systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 06 03:38:33 gbvpi-bedroom systemd[1]: volumio.service: Consumed 20.982s CPU time. Dec 06 03:38:33 gbvpi-bedroom go-librespot[12429]: time="2025-12-06T03:38: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 06 03:38:33 gbvpi-bedroom systemd[1]: Started volumio.service - Volumio Backend Module. Dec 06 03:38:33 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:33 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:33 gbvpi-bedroom systemd[1]: dynamicswap.service: Deactivated successfully. Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ------------------------------------------- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ----- Volumio3 ---- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ------------------------------------------- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ----- System startup ---- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ------------------------------------------- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: MYVOLUMIO Environment detected Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Plugin folders cleanup Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning into folder /volumio/app/plugins/ Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning category audio_interface Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning category miscellanea Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning category music_service Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning category plugins.json Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning category system_controller Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning category user_interface Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning into folder /data/plugins/ Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Scanning category music_service Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Plugin folders cleanup completed Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ------------------------------------------- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ----- Core plugins startup ---- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: ------------------------------------------- Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Loading plugins from folder /volumio/app/plugins/ Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Adding plugin upnp to MyMusic Plugins Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Loading plugins from folder /data/plugins/ Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Loading plugin "system"... Dec 06 03:38:34 gbvpi-bedroom volumio[12451]: info: Loading plugin "appearance"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "network"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Refreshing Cached IP Addresses Dec 06 03:38:35 gbvpi-bedroom sudo[12483]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 03:38:35 gbvpi-bedroom sudo[12483]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:35 gbvpi-bedroom sudo[12485]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 03:38:35 gbvpi-bedroom sudo[12485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:35 gbvpi-bedroom sudo[12483]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "services"... Dec 06 03:38:35 gbvpi-bedroom sudo[12485]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "alsa_controller"... Dec 06 03:38:35 gbvpi-bedroom sudo[12492]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 06 03:38:35 gbvpi-bedroom sudo[12492]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "wizard"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "networkfs"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Starting Udev Watcher for removable devices Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Ignoring mount for partition: boot Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Ignoring mount for partition: volumio Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Ignoring mount for partition: volumio_data Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "volumio_command_line_client"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "upnp"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: [1765010315584] Starting Upmpd Daemon Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "my_music"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "mpd"... Dec 06 03:38:35 gbvpi-bedroom volumio[12451]: info: Loading plugin "upnp_browser"... Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Loading plugin "alarm-clock"... Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Loading plugin "airplay_emulation"... Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Starting Shairport Sync Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Loading plugin "last_100"... Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Loading plugin "webradio"... Dec 06 03:38:36 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 139. Dec 06 03:38:36 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Loading plugin "i2s_dacs"... Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: I2S DAC not set, start Auto-detection Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Loading plugin "volumiodiscovery"... Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: *** WARNING *** For more information see Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 03:38:36 gbvpi-bedroom node[12451]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: *** WARNING *** For more information see Dec 06 03:38:36 gbvpi-bedroom node[12451]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 03:38:36 gbvpi-bedroom node[12451]: *** WARNING *** For more information see Dec 06 03:38:36 gbvpi-bedroom node[12451]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 06 03:38:36 gbvpi-bedroom node[12451]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 06 03:38:36 gbvpi-bedroom node[12451]: *** WARNING *** For more information see Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 06 03:38:36 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:36 gbvpi-bedroom go-librespot[12516]: go-librespot daemon starting... Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Discovery: Started advertising with name: GBVPi-Bedroom Dec 06 03:38:36 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:36-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:36 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:36-05:00" level=debug msg="app state loaded" Dec 06 03:38:36 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:36-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 03:38:36 gbvpi-bedroom volumio[12451]: info: Loading plugin "jellyfin"... Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading plugin "spop"... Dec 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-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 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-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 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-05:00" level=info msg="zeroconf server listening on port 36795" Dec 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-05:00" level=debug msg="obtained new client token: AAAN8+cpe/suOZQF66mqZs7eHxrkZcA5y8PnwxrHU7hwRmnzQ9uE6AnD14ydqmKhz2E5DqvSZQEZuFw3G4x4j4B9cFK4Kkqcrar6Z6OoxUvKaeF2J/IZwMm+k60fitG5yCbUf5NI1IpRfDb537u/E+GfYkRoXbRP6TahEbiLBNPsA8034Z55JfNL6Sq6qa20CCOotMwBCLVGi2Hfstgkz67Nwgb16H0Z7Trp4FXtYw0oc/vLEG/UTPiW/Q==" Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading plugin "outputs"... Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading plugin "albumart"... Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Plugin example_plugin is not enabled Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading plugin "inputs"... Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading plugin "updater_comm"... Dec 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Plugin mpdemulation is not enabled Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading plugin "rest_api"... Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading plugin "websocket"... Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Starting Socket.io Server version 1.7.4 Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Loading i18n strings for locale en Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: Updating browse sources language Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::initPlayerControls Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: Express server listening on port 3000 Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: [Metrics] WebUI: 3s 673.20ms Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::resetVolumioState Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::getcurrentVolume Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-05:00" level=debug msg="completed challenge" Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Volumio Network Manager: Network status updated: 2 Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: VolumeController:: Volume=91 Mute =false Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::pushState Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioPushState Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::updateTrackBlock Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrackBlock Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioRetrievevolume Dec 06 03:38:37 gbvpi-bedroom volumio[12526]: Forking 3 albumart workers Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Reloading queue from file Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::setRepeat null single undefined Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::pushState Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioPushState Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::setRandom null Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::pushState Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioPushState Dec 06 03:38:37 gbvpi-bedroom volumio[12451]: info: Setting Device type: Raspberry PI Dec 06 03:38:37 gbvpi-bedroom go-librespot[12517]: time="2025-12-06T03:38:37-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 06 03:38:37 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:37 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03112 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: VolumeController:: Volume=91 Mute =false Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::pushState Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioPushState Dec 06 03:38:38 gbvpi-bedroom volumio-remote-updater[11354]: [2025-12-06 03:38:38] [connect] Successful connection Dec 06 03:38:38 gbvpi-bedroom volumio-remote-updater[11354]: [2025-12-06 03:38:38] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765010318 101 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: 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 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Completed loading Core Plugins Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Preparing to generate the ALSA configuration file Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Asound.conf file written Dec 06 03:38:38 gbvpi-bedroom sudo[12583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 06 03:38:38 gbvpi-bedroom sudo[12583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:38 gbvpi-bedroom sudo[12583]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Output device has changed, restarting MPD Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Output device has changed, restarting Shairport Sync Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:38 gbvpi-bedroom sudo[12590]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 03:38:38 gbvpi-bedroom sudo[12590]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:38 gbvpi-bedroom sudo[12590]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:38 gbvpi-bedroom sudo[12591]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 03:38:38 gbvpi-bedroom sudo[12591]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: ___________ START PLUGINS ___________ Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: ControllerMpd::onStart: Initializing MPD Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Creating MPD Configuration file Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: [1765010318299] CoreMusicLibrary::Adding element Media Servers Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 06 03:38:38 gbvpi-bedroom sudo[12599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 03:38:38 gbvpi-bedroom sudo[12599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:38 gbvpi-bedroom sudo[12599]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 03:38:38 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.255s CPU time. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 03:38:38 gbvpi-bedroom sudo[12601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 03:38:38 gbvpi-bedroom sudo[12601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: [1765010318458] CoreMusicLibrary::Adding element Last_100 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 03:38:38 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: [1765010318464] CoreMusicLibrary::Adding element Webradio Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Initializing BBC Radios Dec 06 03:38:38 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Discovery: Getting this device information Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: [1765010318611] CoreMusicLibrary::Adding element Jellyfin Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: Cannot find translation for source Jellyfin Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: 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/4ca3014131d666da7f92ae9ddc7e7309/Images/Primary?maxWidth=500&maxHeight=500&quality=90","artist":"Robert Pollard","mute":false,"status":"stop","track":"Run Son Run","volume":91},"type":"device"} Dec 06 03:38:38 gbvpi-bedroom sudo[12615]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 03:38:38 gbvpi-bedroom sudo[12615]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 03:38:38 gbvpi-bedroom sudo[12615]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: Creating Spotify config file Dec 06 03:38:38 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:38 gbvpi-bedroom volumio[12547]: Starting albumart workers Dec 06 03:38:38 gbvpi-bedroom volumio[12550]: Starting albumart workers Dec 06 03:38:39 gbvpi-bedroom volumio[12549]: Starting albumart workers Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Volumio Calling Home Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Discovery: adding 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Discovery: Found device GBVPi-Bedroom Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Discovery: this is already registered, 74ce6260-2045-48bb-acbd-0b75ccb5d93e Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Discovery: Found device GBVPi-Bedroom Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: MPD Permissions set Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: MPD Permissions set Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Volumio called home Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Spotify config file written Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: 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 06 03:38:39 gbvpi-bedroom sudo[12647]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 06 03:38:39 gbvpi-bedroom sudo[12647]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom sudo[12492]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: No need to fix Spotify hosts Dec 06 03:38:39 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:39 gbvpi-bedroom go-librespot[12654]: go-librespot daemon starting... Dec 06 03:38:39 gbvpi-bedroom sudo[12647]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:39 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:39-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:39 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:39-05:00" level=debug msg="app state loaded" Dec 06 03:38:39 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:39-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: [jellyfin-poller] Polled HTTPS://jellyfin.lukeaurio.net: online Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Starting Shairport Sync Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Starting Shairport Sync Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: Starting Shairport Sync Dec 06 03:38:39 gbvpi-bedroom sudo[12674]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 03:38:39 gbvpi-bedroom sudo[12674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:39 gbvpi-bedroom volumio[12451]: info: An error occurred while refreshing Spotify Token Error: Bad Request Dec 06 03:38:39 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:39 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:39-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 06 03:38:39 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:39-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 06 03:38:39 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:39-05:00" level=info msg="zeroconf server listening on port 35177" Dec 06 03:38:39 gbvpi-bedroom sudo[12676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 03:38:39 gbvpi-bedroom sudo[12676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:39 gbvpi-bedroom sudo[12678]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 03:38:39 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 03:38:39 gbvpi-bedroom sudo[12678]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:39 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 03:38:39 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:39 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.664s CPU time. Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:40 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:40-05:00" level=debug msg="obtained new client token: AADLTOSGNaGFqUBevIth1euYwj0u5Fzjv2HGFQV0rl5PCx4UdEwvN4zR34XMtP072EFbrdGvyRUEyzINOUFglrqDvSHgzqQWrni7tVikXnxIHRiv5rnuNHyABfdA4zbd2EVUYZsue0+F15iLXQD/nisERkW5/n5lEo4NQ2X88QQwvYDiw23Eo2r+ut+zxy2Pg+DezNTm6pMfe5eXA8AU7DFOkruyoUAsamFS3Oso2ZdzuarJLqABWuA=" Dec 06 03:38:40 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:40 gbvpi-bedroom sudo[12674]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Shairport-Sync Started Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: Error adding Membership: Error: addMembership EINVAL Dec 06 03:38:40 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 03:38:40 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:40-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:40 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 03:38:40 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:40 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:40 gbvpi-bedroom sudo[12678]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:40 gbvpi-bedroom sudo[12676]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Shairport-Sync Started Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Shairport-Sync Started Dec 06 03:38:40 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:40-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:40 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38:40-05:00" level=debug msg="completed challenge" Dec 06 03:38:40 gbvpi-bedroom go-librespot[12660]: time="2025-12-06T03:38: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 06 03:38:40 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:40 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:40 gbvpi-bedroom mpd[12630]: 2025-12-06T03:38:40 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 06 03:38:40 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 06 03:38:40 gbvpi-bedroom sudo[12591]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:40 gbvpi-bedroom sudo[12601]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Completed starting Core Plugins Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: ------------------------------------------- Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: ----- MyVolumio plugins startup ---- Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: ------------------------------------------- Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: error: MPD error: The expression evaluated to a falsy value: Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: assert.ok(self.idling) Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: error: The expression evaluated to a falsy value: Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: assert.ok(self.idling) Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: MPD running with PID12630 Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: ,establishing connection Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: error: updateQueue error: null Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: error: updateQueue error: null Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:38:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:38:42 gbvpi-bedroom volumio[12451]: info: go-librespot daemon successfully initialized Dec 06 03:38:42 gbvpi-bedroom volumio[12451]: info: Discovery: Browse raised the following error Error: dns service error: unknown Dec 06 03:38:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 140. Dec 06 03:38:43 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:43 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:43 gbvpi-bedroom go-librespot[12703]: go-librespot daemon starting... Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=debug msg="app state loaded" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:43 gbvpi-bedroom sudo[12711]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 03:38:43 gbvpi-bedroom sudo[12711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:43 gbvpi-bedroom sudo[12713]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 03:38:43 gbvpi-bedroom sudo[12713]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:43 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 06 03:38:43 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 06 03:38:43 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 06 03:38:43 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 06 03:38:43 gbvpi-bedroom sudo[12711]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:43 gbvpi-bedroom sudo[12713]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:43 gbvpi-bedroom volumio[12451]: info: Successfully started MPD Monitor Dec 06 03:38:43 gbvpi-bedroom mpd_monitor.sh[12717]: MPD Monitor Service: Starting MPD Monitor Service Dec 06 03:38:43 gbvpi-bedroom volumio[12451]: info: Successfully started MPD Monitor Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-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 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-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 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=info msg="zeroconf server listening on port 38205" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=debug msg="obtained new client token: AACptgVMnZIoT5TaWCG67uVoalGOJPk2kF18lTJyuA8KrGSztEVPcoCfTHiQW/bO0T6b9H1Tp3+s7rMAmcS86UnooGAghRtkWcfbL+b0sNf5cbFUJxJWtZLBr9S3MEPXX0SmGovnI8fpfEbas7FgeOcu00eMj1XRReK5WfiI9n+sRf57cWiSQytZ1kAiAjGpxjPsOhIbPq7+cSGH6fg9PgCKdcfvsms/iMV4ORs1d8RH0WCT8How3z2s3w==" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38:43-05:00" level=debug msg="completed challenge" Dec 06 03:38:43 gbvpi-bedroom go-librespot[12704]: time="2025-12-06T03:38: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 06 03:38:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:45 gbvpi-bedroom volumio[12451]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 06 03:38:45 gbvpi-bedroom sudo[12736]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 06 03:38:45 gbvpi-bedroom sudo[12736]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:45 gbvpi-bedroom sudo[12738]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 06 03:38:45 gbvpi-bedroom sudo[12738]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:45 gbvpi-bedroom sudo[12736]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:45 gbvpi-bedroom sudo[12738]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:45 gbvpi-bedroom sudo[12741]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 06 03:38:45 gbvpi-bedroom sudo[12741]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:45 gbvpi-bedroom sudo[12741]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:45 gbvpi-bedroom volumio[12451]: info: Upmpdcli Daemon Started Dec 06 03:38:45 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:45 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:47 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 141. Dec 06 03:38:47 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:47 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:47 gbvpi-bedroom go-librespot[12744]: go-librespot daemon starting... Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=debug msg="app state loaded" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-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 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-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 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-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 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=info msg="zeroconf server listening on port 45101" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=debug msg="obtained new client token: AACQpI3viOGKo/tFZclXQSLHQPQhI6E9SB5i++qh7JIDLj1XElFuc0XX4K0Xtuvwrwdo6e6EvkwHgG3aMs83c1Xlcu+Sr8MJD5d8XlOoy1wLDt7VHk2CRJPCJxtHT2Et9N+gKPK31m+oIlUcmiL6XG+uvSzGhTOzl7hS8wCig5AkqsFxRlAT6KDvfHXNRxY1F47r/p3W/fM20g6guX1FEyw0NywBesh3hgoFnLNhD7UMr2iiw2DLm0Pj+g==" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-05:00" level=debug msg="completed challenge" Dec 06 03:38:47 gbvpi-bedroom go-librespot[12745]: time="2025-12-06T03:38:47-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 06 03:38:47 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:47 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: Adding plugin bluetooth to MyMusic Plugins Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: Adding plugin multiroom to MyMusic Plugins Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: Adding plugin metavolumio to MyMusic Plugins Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: Adding plugin cd_controller to MyMusic Plugins Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 06 03:38:48 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: Starting MyVolumio Remote Streaming Endpoints Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: MyVolumio login type: Token Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: Streaming services startup Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: Starting Streaming Daemon Dec 06 03:38:49 gbvpi-bedroom sudo[12753]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 03:38:49 gbvpi-bedroom sudo[12753]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 06 03:38:49 gbvpi-bedroom sudo[12753]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: error: Cannot start Volumio Streaming Daemon Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:49 gbvpi-bedroom volumio[12451]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MyVolumio token set successfully Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MYVOLUMIO: Adding device Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MYVOLUMIO: Evaluating Server Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MyVolumio Plan changed: premium Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Removing browser output: myVolumio user plan is not superstar Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Removing audio output: Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MYVOLUMIO: Adding device Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MYVOLUMIO: Evaluating Server Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Remote config written successfully Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Starting Tunnel 1 Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Starting Tunnel Connection Checker Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Completed starting MyVolumio Plugin Dec 06 03:38:50 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 142. Dec 06 03:38:50 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:50 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:50 gbvpi-bedroom go-librespot[12786]: go-librespot daemon starting... Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=debug msg="app state loaded" Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MYVolumio Device enabled Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: MyVolumio status changed Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Streaming services startup Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: Starting Streaming Daemon Dec 06 03:38:50 gbvpi-bedroom sudo[12805]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 06 03:38:50 gbvpi-bedroom sudo[12805]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Dec 06 03:38:50 gbvpi-bedroom sudo[12805]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=info msg="zeroconf server listening on port 43579" Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Dec 06 03:38:50 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Dec 06 03:38:50 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:50-05:00" level=debug msg="obtained new client token: AACeJwAZBJJtwn5KGvjAmr5OhnZmX5UVjORvuvLiAnW2SnJ0kkuhIN2qTiDE4sB+z6o4KC6FEKZ/5JjXNwZXLL6zIys00ECCWmefOrpMOVqGzY91rmFRpt4Vk5b3s3oYs9YTFWJd+xvQvP8FiB8I11YPfQ2Xze7ygiPzlIKM/0WChdYcn0BCT8VeDUdi6Nm7E3UtCAAzlJ6qaU5LBKrUr+3sPBQs1aTiqumkqaiqiuqHIpJent9wGcsMKw==" Dec 06 03:38:51 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:51-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Dec 06 03:38:51 gbvpi-bedroom sudo[12811]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Dec 06 03:38:51 gbvpi-bedroom sudo[12811]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:51 gbvpi-bedroom sudo[12811]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: /usr/bin/mkdir: cannot create directory ‘/tmp/hls’: File exists Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: MultiRoom plugin initialized Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: STOPPING SNAPCLIENT Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: Snap server stop Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: STOPPING volumioStreaming Dec 06 03:38:51 gbvpi-bedroom sudo[12828]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Dec 06 03:38:51 gbvpi-bedroom sudo[12828]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Dec 06 03:38:51 gbvpi-bedroom sudo[12830]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Dec 06 03:38:51 gbvpi-bedroom sudo[12830]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:51 gbvpi-bedroom sudo[12832]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Dec 06 03:38:51 gbvpi-bedroom sudo[12832]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Dec 06 03:38:51 gbvpi-bedroom sudo[12836]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Dec 06 03:38:51 gbvpi-bedroom sudo[12836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Dec 06 03:38:51 gbvpi-bedroom sudo[12836]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Dec 06 03:38:51 gbvpi-bedroom sudo[12828]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Dec 06 03:38:51 gbvpi-bedroom sudo[12830]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Dec 06 03:38:51 gbvpi-bedroom sudo[12832]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Loading plugin "qobuzconnect"... Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: Preparing to generate the ALSA configuration file Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: Setting Geolocation for MyVolumio to us1 Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: Reading ALSA contributions from plugins. Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: Setting Geolocation for MyVolumio to us4 Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: Removed streaming files Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: volumioStreaming STOPPED Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: SNAPSERVER STOPPED Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: MRS: SNAPCLIENT STOPPED Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: error: Cannot start Volumio Streaming Daemon Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: Asound.conf file written Dec 06 03:38:51 gbvpi-bedroom sudo[12841]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Dec 06 03:38:51 gbvpi-bedroom sudo[12841]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:51 gbvpi-bedroom sudo[12841]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: Output device has changed, restarting MPD Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: Output device has changed, restarting Shairport Sync Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:51 gbvpi-bedroom sudo[12847]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 06 03:38:51 gbvpi-bedroom sudo[12847]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:51 gbvpi-bedroom sudo[12847]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:52 gbvpi-bedroom sudo[12850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 06 03:38:52 gbvpi-bedroom sudo[12850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin audio_interface.bluetooth Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: [FUNC] onStart Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: Starting Volumio Bluetooth Service Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: Boot config /etc/bluetooth/volumio.conf: cache mode = tmp Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: [metaCache] Directory exists and is ready. Dec 06 03:38:52 gbvpi-bedroom systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin audio_interface.multiroom Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , pushMultiRoomStatus Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: MRS: Pushing multiroomSync output for this device Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: MRS: Pushing multiroomSync output Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding audio output: Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding audio output: Dec 06 03:38:52 gbvpi-bedroom systemd[1]: mpd.service: Deactivated successfully. Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin miscellanea.metavolumio Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding METAVOLUMIO REST API Endpoints Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding metavolumio REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding getSimilarArtists REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding getSimilarAlbums REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding getSimilarTracks REST Endpoint for plugin: miscellanea/metavolumio Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin miscellanea.manifestui Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.cd_controller Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Preparing CD Folders Dec 06 03:38:52 gbvpi-bedroom bluetoothd[807]: Path / reserved for Adv Monitor app :1.16264 Dec 06 03:38:52 gbvpi-bedroom systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding CD REST API Endpoints Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Adding cdPostRip REST Endpoint for plugin: music_service/cd_controller Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Starting UDEV Watcher for CD Dec 06 03:38:52 gbvpi-bedroom systemd[1]: mpd.service: Consumed 1.902s CPU time. Dec 06 03:38:52 gbvpi-bedroom systemd[1]: mpd.socket: Deactivated successfully. Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: Detecting CD presence with UDEV Dec 06 03:38:52 gbvpi-bedroom systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 06 03:38:52 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: networkfs , getUdevDevices Dec 06 03:38:52 gbvpi-bedroom systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 06 03:38:52 gbvpi-bedroom bluetoothd[807]: Adv Monitor app :1.16264 disconnected from D-Bus Dec 06 03:38:52 gbvpi-bedroom systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 06 03:38:52 gbvpi-bedroom systemd[1]: Starting mpd.service - Music Player Daemon... Dec 06 03:38:52 gbvpi-bedroom sudo[12867]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 06 03:38:52 gbvpi-bedroom sudo[12867]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 06 03:38:52 gbvpi-bedroom sudo[12867]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:52 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:52-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:52 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:52-05:00" level=debug msg="completed challenge" Dec 06 03:38:53 gbvpi-bedroom go-librespot[12795]: time="2025-12-06T03:38:53-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 06 03:38:53 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:53 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:53 gbvpi-bedroom mpd[12869]: 2025-12-06T03:38:53 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 06 03:38:53 gbvpi-bedroom systemd[1]: Started mpd.service - Music Player Daemon. Dec 06 03:38:53 gbvpi-bedroom sudo[12850]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:56 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 143. Dec 06 03:38:56 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:56 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:56 gbvpi-bedroom go-librespot[12887]: go-librespot daemon starting... Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=debug msg="app state loaded" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-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 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-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 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-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 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=info msg="zeroconf server listening on port 35403" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=debug msg="obtained new client token: AACmU6yZWLjuAAIrEtK+rE6+6uraIIo8PEBfw4w2U2VVQDSO2ccqe6iPuQUaZLyHx1AkeQ8MU0Glct/cTQtrGM0zzer2AbLJhfG7gN397RE8DTX3SXoXyUhsSQ13HA7vOd0myV66qgUi0RLCmQxP89XraCupfJeuAUGf9BVgaSrQdSfftpYw7S+XQh1XzyLU7PlZxw5gM9R4CnZ/qqOcT1D/3TbBOHhaTdaTAruP1zB2fXJMEeBKpFneRw==" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=debug msg="completed keyexchange" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-05:00" level=debug msg="completed challenge" Dec 06 03:38:56 gbvpi-bedroom go-librespot[12888]: time="2025-12-06T03:38:56-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 06 03:38:56 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:38:56 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: warn: [cd-plugin] cdspeedctl: device or media not ready Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding inputs REST Endpoints Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Scanning Audio Inputs Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Checking against Known Cards name Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding Server instance for streaming Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: error: Hi Res Audio Failed Login: Missing Login Data Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding HIGHRESAUDIO REST API Endpoints Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Dec 06 03:38:57 gbvpi-bedroom sudo[12899]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: QobuzConnect: Starting Qobuz Connect socket and service Dec 06 03:38:57 gbvpi-bedroom sudo[12899]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding TIDAL REST API Endpoints Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Stopping AccessToken refresher cron for QOBUZ Dec 06 03:38:57 gbvpi-bedroom sudo[12906]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Dec 06 03:38:57 gbvpi-bedroom sudo[12906]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:57 gbvpi-bedroom systemd[1]: vtcs.service: Deactivated successfully. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Dec 06 03:38:57 gbvpi-bedroom sudo[12899]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: AccessToken refresher cron started for QOBUZ Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding QOBUZ REST API Endpoints Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Updating MyVolumio device info Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:57 gbvpi-bedroom sudo[12906]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Updating MyVolumio device info Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: MRS: Getting audio outputs on start Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: MRS: Requesting all other devices output Dec 06 03:38:57 gbvpi-bedroom sudo[12909]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Dec 06 03:38:57 gbvpi-bedroom sudo[12909]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Successfully Added MyVolumio device Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12295]: 20251206 03:38:57.269 [12295.12295] INFO SampleApp: Stopping Local configuration server Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Successfully Added MyVolumio device Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: MPD Permissions set Dec 06 03:38:57 gbvpi-bedroom sudo[12912]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Dec 06 03:38:57 gbvpi-bedroom sudo[12912]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:38:57 gbvpi-bedroom sudo[12912]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: error: updateQueue error: null Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioStop Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::stop Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Starting Shairport Sync Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: MRS: Found cast device: SmartTV-4K-fe72c264393a59c76d38e27b8168114d Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding audio output: Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: MRS: Found cast device: Google-Home-Mini-f209fa314cb426d40a59bcf66354ddc9 Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Adding audio output: Dec 06 03:38:57 gbvpi-bedroom sudo[12927]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 06 03:38:57 gbvpi-bedroom sudo[12927]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:57 gbvpi-bedroom sudo[12929]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Dec 06 03:38:57 gbvpi-bedroom sudo[12929]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Successfully Updated MyVolumio device Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Successfully Updated MyVolumio device Dec 06 03:38:57 gbvpi-bedroom autossh[12268]: received signal to exit (15) Dec 06 03:38:57 gbvpi-bedroom systemd[1]: qobuz-connect.service: Deactivated successfully. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: shairport-sync.service: Deactivated successfully. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: shairport-sync.service: Consumed 1.614s CPU time. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: sshtunnel.service: Deactivated successfully. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Dec 06 03:38:57 gbvpi-bedroom sudo[12909]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 06 03:38:57 gbvpi-bedroom sudo[12927]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:57 gbvpi-bedroom systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Shairport-Sync Started Dec 06 03:38:57 gbvpi-bedroom sudo[12929]: pam_unix(sudo:session): session closed for user root Dec 06 03:38:57 gbvpi-bedroom autossh[12935]: port set to 0, monitoring disabled Dec 06 03:38:57 gbvpi-bedroom autossh[12935]: starting ssh (count 1) Dec 06 03:38:57 gbvpi-bedroom autossh[12935]: ssh child pid is 12938 Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Executing endpoint qc_getconfig Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.638 [12932.12932] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: Remote SSH Started Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.642 [12932.12932] INFO VolumeManager: [0x1969588]: Setting new playback volume: 75 Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.642 [12932.12932] INFO VolumeManager: [0x1969588]: Setting new mute state: 0 Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.642 [12932.12932] INFO QobuzConnect: [0x1969f58]: Client initialized! Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.642 [12932.12932] INFO SampleApp: Starting Avahi advertising, name: GBVPi-Bedroom, service name: _qobuz-connect._tcp Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.675 [12932.12932] INFO LocalConfigManager: [0x1968e68]: Starting Local Configuration server Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.675 [12932.12932] INFO SampleApp: Starting Local configuration server Dec 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.675 [12932.12932] INFO SampleApp: Connected to UNIX socket client 0x1953818 Dec 06 03:38:57 gbvpi-bedroom volumiossh-tunnel[12938]: Warning: Permanently added '[us4.myvolumio.org]:2222' (ED25519) to the list of known hosts. Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: QobuzConnect: QOBUZ Connect daemon connected Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: 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 06 03:38:57 gbvpi-bedroom qobuz-connect[12932]: 20251206 03:38:57.787 [12932.12932] INFO SampleApp: Playback volume changed: 75 Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:38:57 gbvpi-bedroom volumio[12451]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 06 03:38:59 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 144. Dec 06 03:38:59 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:59 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:38:59 gbvpi-bedroom go-librespot[12958]: go-librespot daemon starting... Dec 06 03:38:59 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:38:59-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:38:59 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:38:59-05:00" level=debug msg="app state loaded" Dec 06 03:38:59 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:38:59-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=info msg="zeroconf server listening on port 40339" Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=debug msg="obtained new client token: AADG/K06/vKsh+ej/RbI+D9FK3W5MyOVGSuGWKDGEqGS/ZNotBmznxkCd4rYKOstjvJkFrYYz+YXwpioK6fKBCuj7c3QwBjCYU1eO+oI1Nu+qcZoneYkgmbSi1+16PFtljxL9OP/9HopMKuPRLp38dp+eZHKCaDzbYqLMnzVnxAd2U3DIVBbT/fPlNOjMWflh9ZxbOQfIAewySQnL0oMiA8Yexhyt/OasQbna8F16oU4CLhUMoKLJh0=" Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: TidalConnect service stoped! Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Dec 06 03:39:00 gbvpi-bedroom sudo[12975]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Dec 06 03:39:00 gbvpi-bedroom sudo[12975]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39:00-05:00" level=debug msg="completed challenge" Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:00 gbvpi-bedroom sudo[12979]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 06 03:39:00 gbvpi-bedroom sudo[12979]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 06 03:39:00 gbvpi-bedroom go-librespot[12959]: time="2025-12-06T03:39: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 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: read ECONNRESET Dec 06 03:39:00 gbvpi-bedroom systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Dec 06 03:39:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:00 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:00 gbvpi-bedroom sudo[12975]: pam_unix(sudo:session): session closed for user root Dec 06 03:39:00 gbvpi-bedroom systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 06 03:39:00 gbvpi-bedroom systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 06 03:39:00 gbvpi-bedroom systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 06 03:39:00 gbvpi-bedroom systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 06 03:39:00 gbvpi-bedroom mpd_monitor.sh[12983]: MPD Monitor Service: Starting MPD Monitor Service Dec 06 03:39:00 gbvpi-bedroom sudo[12979]: pam_unix(sudo:session): session closed for user root Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Successfully started MPD Monitor Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Executing endpoint tc_getconfig Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Dec 06 03:39:00 gbvpi-bedroom vtcs[12981]: STARTING TidalConnect services, version: 1.5.2.56 Dec 06 03:39:00 gbvpi-bedroom vtcs[12981]: STARTED TidalConnect services. Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Executing endpoint tc_connect Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Connecting to TidalConnect Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::servicePushState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::pushState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioPushState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: MRS: Pushing multiroomSync output update for this device Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: MRS: Pushing multiroomSync output Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::servicePushState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreStateMachine::pushState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioPushState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: MRS: Pushing multiroomSync output update for this device Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: MRS: Pushing multiroomSync output Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CorePlayQueue::getTrack 0 Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received tidalconnect Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.KgLfU6XUUlR7svHZAvNpgZIq9af1.66712a116082b2e6ca4ffe3109a843e6.state.status' Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:00 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: TidalConnect service started! Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: [Metrics] CommandRouter: 28s 957.97ms Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumiosetStartupVolume Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::Close All Modals sent Dec 06 03:39:03 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::Close All Modals sent Dec 06 03:39:03 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 145. Dec 06 03:39:03 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:03 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:03 gbvpi-bedroom go-librespot[13001]: go-librespot daemon starting... Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=debug msg="app state loaded" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-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 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-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 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=info msg="zeroconf server listening on port 45697" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=debug msg="obtained new client token: AACnyJ1bUt/r7kErsvQV2W0f91AbAP6qJnb1I8M8IFYnlwppGqSXXIwrmsYk5NRL/ECAqFyXnt+9HN8IY+tBAnXBwRSpgUKcx8fyNJWuTG2NggGxqti2t1IZog6Pq8uLGtLiUv/wrXoL1C3bYJL5/lUI9TeBRYeCY5URYnuraYa5p3jQpIZr/T0KP2svVpuJVqI7tHf7XOgnszciuzd71MNVCSmLEeKTukWCZ9xh6CEbooNoVWyuytFQUQ==" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:03 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39:03-05:00" level=debug msg="completed challenge" Dec 06 03:39:04 gbvpi-bedroom go-librespot[13002]: time="2025-12-06T03:39: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 06 03:39:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:04 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:04 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 06 03:39:04 gbvpi-bedroom volumio[12451]: 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 06 03:39:04 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:04 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 06 03:39:04 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 06 03:39:04 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 06 03:39:06 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:06 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:07 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 146. Dec 06 03:39:07 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:07 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:07 gbvpi-bedroom go-librespot[13026]: go-librespot daemon starting... Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=debug msg="app state loaded" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39: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-gew4.spotify.com:80]" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-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 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-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 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=info msg="zeroconf server listening on port 46457" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=debug msg="obtained new client token: AADdcc1fZshcLXMITa+YoAz0OobOqYVtKsEZIwUI43CmUbeXfA2qMTi6EsHXC5zFHvS5u6/+dGqrcSVIC0Xl2aFs2puDo5s8doYxZe8ah4S7bitUBygE8TSiMkwrf3w24b2D/LLRbKOBI3c9+t9/3YmwUq1ku2GA4LhzfGnO5e51SCJaKRODNnu3ILMtyKse8GYb1vA30gHH1pKg7C/sA30H09ak90a68bTnf7KgG5Fk9/laJIG1I5oImA==" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=debug msg="completed challenge" Dec 06 03:39:07 gbvpi-bedroom go-librespot[13027]: time="2025-12-06T03:39:07-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 03:39:07 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:07 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 06 03:39:09 gbvpi-bedroom volumio-remote-updater[11354]: Test mode enabled Dec 06 03:39:09 gbvpi-bedroom volumio-remote-updater[11354]: Alpha mode disabled Dec 06 03:39:09 gbvpi-bedroom volumio-remote-updater[11354]: Alpha legacy test mode disabled Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetBrowseSources Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"

ANNOUNCEMENT

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

FIX

\n
    \n
  • Nodejs 20.5.1 version pinning with static package fallback
    • \n
\n","title":"Update v4.073","updateavailable":true} Dec 06 03:39:09 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Dec 06 03:39:10 gbvpi-bedroom volumio[12451]: info: BOOT COMPLETED Dec 06 03:39:10 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 147. Dec 06 03:39:10 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:10 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:10 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:10 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:10 gbvpi-bedroom go-librespot[13038]: go-librespot daemon starting... Dec 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-05:00" level=debug msg="app state loaded" Dec 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-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 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-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 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-05:00" level=info msg="zeroconf server listening on port 39245" Dec 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-05:00" level=debug msg="obtained new client token: AACQJxZbdkrvI8nRS9UFW2JEq74VDQvKTHlYay/emnd2CscthOBNtbmtqFmtj3i54S4mPgkKSfzhZR6wiCAusvK7VpT7inZ20lrZe0ClN8II3BFonB0TmJNMFDnzzXq/2nzu7p8yl0RvcpWvFrYEWRlZpZqG1NAvhvwCTXVOtOas9WtGK2LMIDfOEq9eZS3VGnQjHYVKxi5KLjfypXlb4Sc/icxtx3224XWRBNoER55QBCcvZfWGoMCpGw==" Dec 06 03:39:10 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:10-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:11 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:11-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:11 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39:11-05:00" level=debug msg="completed challenge" Dec 06 03:39:11 gbvpi-bedroom go-librespot[13039]: time="2025-12-06T03:39: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 06 03:39:11 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:11 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:12 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:12 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:14 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 148. Dec 06 03:39:14 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:14 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:14 gbvpi-bedroom go-librespot[13046]: go-librespot daemon starting... Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=debug msg="app state loaded" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-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 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-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 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-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 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=info msg="zeroconf server listening on port 34969" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=debug msg="obtained new client token: AADHxyhLvBnbCr+AaffJpm3f5c9WVOgJFjE1pH5nbUXNJKous0g0fAP/HDeR0wqO6Rfd9Lxlmknqvaz+ifjt19dJP+Xdd7SqZ0x1j1vNkDyhx9TLSIbmZtwhXOHmbeKW5iQC4nXuuoTAnGTc1EhirWHE56IV1nxnuwUGYBdg5vYS/KpQrbQD08JjDBI5P5Z6xKL9QhRCSvX5D5/lIFSpFRI4iSeR5RYAAeTWxS/d/30Oj/1JuvUqkTC+vg==" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-05:00" level=debug msg="completed challenge" Dec 06 03:39:14 gbvpi-bedroom go-librespot[13047]: time="2025-12-06T03:39:14-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 06 03:39:14 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:14 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:15 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:15 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:17 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 149. Dec 06 03:39:17 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:17 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:17 gbvpi-bedroom go-librespot[13070]: go-librespot daemon starting... Dec 06 03:39:17 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:17-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:17 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:17-05:00" level=debug msg="app state loaded" Dec 06 03:39:17 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:17-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39: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 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39: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 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39: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 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:18-05:00" level=info msg="zeroconf server listening on port 37587" Dec 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:18-05:00" level=debug msg="obtained new client token: AAD9GqTcdOOW0efFsxVEH3lw+IWNE9dAXjsHfU2+zurzIfuyrGf84J27zaj3OFi+VnPrLX0DQgZ71f0TjagX1iWhqFE31HSHdNFQ8AJv4xYuxyYadLzsVMUXvGEqMTowe7AUV7uNm28+0+/01hIfoPFrDTap+CsouUh1+bMNgVUP7kktFaQYLynDo7jjzq821RuRCjpZURl+JaxaWVgL4OdYscfW0fJFaZC0K0vsADvo8ts/vUiFiLg=" Dec 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:18-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:18-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:18-05:00" level=debug msg="completed challenge" Dec 06 03:39:18 gbvpi-bedroom go-librespot[13071]: time="2025-12-06T03:39:18-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 06 03:39:18 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:18 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:18 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:18 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:20 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:20 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:20 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:20 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:20 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:20 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:21 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 150. Dec 06 03:39:21 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:21 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:21 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:21 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:21 gbvpi-bedroom go-librespot[13081]: go-librespot daemon starting... Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=debug msg="app state loaded" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-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 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-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 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=info msg="zeroconf server listening on port 38203" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=debug msg="obtained new client token: AACq9ECjrVKftoeB6KvHRmRimHBa48/KKHyVbqJw/JIWkWK/roDTK5JLyZZEL+rUL7oHa1aeYDXRiR84vmbvM1bvu3qFwXn2Pp+0L8pnW2QUa9qZcDcQclFlLDKX5cW562IlN+Oq14kRBiE1Q+gbNxeOEr7G+Ri6b6i0gWWtsRfbYPL6DOXLb8yi5VPS7GqNbd+Lo/XVH+t1ob/o2EeKLV3fqo66ieo3koFqSbBkk1xXUfGG7PmwZmjsxg==" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39:21-05:00" level=debug msg="completed challenge" Dec 06 03:39:21 gbvpi-bedroom go-librespot[13082]: time="2025-12-06T03:39: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 06 03:39:21 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:21 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:24 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:24 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:24 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 151. Dec 06 03:39:24 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:24 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:24 gbvpi-bedroom go-librespot[13089]: go-librespot daemon starting... Dec 06 03:39:24 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:24-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:24 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:24-05:00" level=debug msg="app state loaded" Dec 06 03:39:24 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:24-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-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 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-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 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-05:00" level=info msg="zeroconf server listening on port 34157" Dec 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-05:00" level=debug msg="obtained new client token: AACjSvRaPhkpjeKMc9ghZpEusSx9QiRADhenfBjgnpfSgyCAAHT3uB3C/+0vxtnAxpXJAyY45c2FxVWSRCnDM3U5Ji72DSjoGTvIpc7wQO2QQT+7BTyXIks2fWsNugv9zMY3ePKDHSPVFasQPo+9AtPbiiQVfDKPbmvcUj7/kP3XWAatHD0SauSkxkf0Ri1x3DFJs1FANbooe4dYaHRyDWlF+be5bUAORmuNBIONcYV2e7L1Kwvnrwc=" Dec 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-05:00" level=debug msg="completed challenge" Dec 06 03:39:25 gbvpi-bedroom go-librespot[13090]: time="2025-12-06T03:39:25-05:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: accesspoint login failed: BadCredentials " Dec 06 03:39:25 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:25 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:27 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:27 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:28 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 152. Dec 06 03:39:28 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:28 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:28 gbvpi-bedroom go-librespot[13111]: go-librespot daemon starting... Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=debug msg="app state loaded" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39: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 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39: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 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39: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 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=info msg="zeroconf server listening on port 44599" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=debug msg="obtained new client token: AAAqRSzcaW6JeJ+h3vScJvyBuTI0umCFpdBRGlC4Ih+jY6pd4pzuVGzAbvavzPoqgu2THgoTVIQszKtj5jZlBkPOI39pIbLepPQiegEDXUx6BO342z+kBHIIn8j77tXbE01cGk+AUYn8gDL8YDt0XGGK3vd+k41a7Ebv35zesMB5IJdWX9Vnufdm3i93FQ9pwq2hPuypoA36VJdtZ1z44nbuC8yprS5fp7FbuJ5kLo0uh2r98QctXjjKBw==" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39: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 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=debug msg="connected to ap-gue1.spotify.com:443" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39:28-05:00" level=debug msg="completed challenge" Dec 06 03:39:28 gbvpi-bedroom go-librespot[13112]: time="2025-12-06T03:39: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 06 03:39:28 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:28 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:30 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:30 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:30 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:30 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:32 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 153. Dec 06 03:39:32 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:32 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:32 gbvpi-bedroom go-librespot[13119]: go-librespot daemon starting... Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=debug msg="app state loaded" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-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 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-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 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-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 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=info msg="zeroconf server listening on port 40183" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=debug msg="obtained new client token: AAD4aEjUPajAxn5KPYbyQgpUVc68Ngr3sWL42cuOjGN8NM9nVNGwOZt5eXTiG8zf1jhQP6VuqccqYVBklB0hBAU4lTphSNMTrWK2iIuYvcgxCrb3SUxCXneMc4uWdykpuY2/y1Q9CPMn/YHSeXkiqHfFJkgwKNgzXbG0lIAvaqFFEmsMIi92ZVc6Q8YktGApIuN7igQmbAO7iXK9Low4MRsM8H5XDgnS8HT6aXGqrLym68JCAn75cbf+FQ==" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39:32-05:00" level=debug msg="completed challenge" Dec 06 03:39:32 gbvpi-bedroom go-librespot[13120]: time="2025-12-06T03:39: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 06 03:39:32 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:32 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:33 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:33 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:35 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 154. Dec 06 03:39:35 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:35 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:35 gbvpi-bedroom go-librespot[13142]: go-librespot daemon starting... Dec 06 03:39:35 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:35-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:35 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:35-05:00" level=debug msg="app state loaded" Dec 06 03:39:35 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:35-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=debug msg="fetched new dealers: [gue1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=debug msg="fetched new spclients: [gue1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=info msg="zeroconf server listening on port 34507" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=debug msg="obtained new client token: AAA9F75gToK4Acs4ZAvW9pYKvR0sWg3MHTt93nZXg9uXm1TWERJLQWC5ttb//UVZp3zwwtvv2vo8ZnSmxvGdR1bPnQ5AKgaeZMkkbsnS7RMILw5FAkEl9GZz1S0YxNt68ktv18ITPnEXVnFOAtT8aEv1aoUOOPJQJOZjjzMC6T9u0XiNPKkcUUZyiLWmNMn9OZGKuvwDeyfediHWKAagdQnbnDD9maHHHRrDbZyTqh5MYkQ9gWCkYfk=" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39:36-05:00" level=debug msg="completed challenge" Dec 06 03:39:36 gbvpi-bedroom go-librespot[13143]: time="2025-12-06T03:39: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 06 03:39:36 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:36 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:36 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:36 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:39 gbvpi-bedroom volumio[12451]: info: UPDATER: Scheduling automatic update Dec 06 03:39:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getAutoUpdateWindowStartTime Dec 06 03:39:39 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::executeOnPlugin: system , getAutoUpdateWindowStopTime Dec 06 03:39:39 gbvpi-bedroom volumio[12451]: info: UPDATER: Auto update will take place at: Sun Dec 07 2025 05:19:01 GMT-0500 (Eastern Standard Time) Dec 06 03:39:39 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:39 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:39 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 155. Dec 06 03:39:39 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:39 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:39 gbvpi-bedroom go-librespot[13150]: go-librespot daemon starting... Dec 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:39-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:39-05:00" level=debug msg="app state loaded" Dec 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:39-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39: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 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39: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 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39: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 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:39-05:00" level=info msg="zeroconf server listening on port 40923" Dec 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:39-05:00" level=debug msg="obtained new client token: AAD1gfF7nX5MeMKKMn10tT9aTOVGEGscKBs2VS4Qt2JGhbjBkqfndYguHea2+gIHe5Djam4r1Zu4HG7wY0Qr/8BmxDDtnnRG3Tw94RB2y+uIoD6MEIUoz/06iKZWwrPgbaXrATpSnRz7C7iHFUYwEV5H62AmQhnQUhrr/5BLjqcaEF7Y8KcVKslN/V4rIWcsjJYTzrsPPSDZ4FKpWoijPnkffghzxI2aMVvmDZI1iDj0dG0qpstXOIorOA==" Dec 06 03:39:39 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:39-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:40 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:40-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:40 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39:40-05:00" level=debug msg="completed challenge" Dec 06 03:39:40 gbvpi-bedroom go-librespot[13151]: time="2025-12-06T03:39: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 06 03:39:40 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:40 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:40 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:40 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:40 gbvpi-bedroom volumio[12451]: info: Listing playlists Dec 06 03:39:42 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:42 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 156. Dec 06 03:39:43 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:43 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:43 gbvpi-bedroom go-librespot[13161]: go-librespot daemon starting... Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=debug msg="app state loaded" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39: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-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-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 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-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 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=info msg="zeroconf server listening on port 37947" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=debug msg="obtained new client token: AAChIpKa7NDu6+SNpN5IA71oLLoSKgPyUSGv6UWuaUGxkhlH3x3zAw54WF04RLWifDfqiQ9VLqfN9UVB1GnNB/vF6JO1rOaBLnDfIOqBUYF03djj8JjF9jwA5P7OeWHYbQu7mtHod245SNJ0EXLgwLmOEaMGeHWWjvI9GGF/OiwUbXkmxiot2V4XP2gycG8PjoTRr71//utrmnsZls3rb/jL1IgIM+tNWXjQN4Xd+eHl9LG7oYjtRZHh0g==" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39:43-05:00" level=debug msg="completed challenge" Dec 06 03:39:43 gbvpi-bedroom go-librespot[13162]: time="2025-12-06T03:39: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 06 03:39:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:43 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:45 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:45 gbvpi-bedroom volumio[12451]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 06 03:39:47 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 157. Dec 06 03:39:47 gbvpi-bedroom systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:47 gbvpi-bedroom systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 06 03:39:47 gbvpi-bedroom go-librespot[13183]: go-librespot daemon starting... Dec 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-05:00" level=info msg="running go-librespot 0.4.0" Dec 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-05:00" level=debug msg="app state loaded" Dec 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-05:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-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 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-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 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-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 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-05:00" level=info msg="zeroconf server listening on port 34571" Dec 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-05:00" level=debug msg="obtained new client token: AAAkShr5d2ef14uHSbKofbaL7VffD98/O9USwRzltX3QUs+ynG7fGgfYiRMbc+OYYlS7nmIDQ9CUN9xdgF2QAouwy61rreqtgSZWXADQgKobTn36kC3N93JdVKgjR3JCgQe1oJeZZf+Pv4jVY2Qdxc+Z3zXc0/62+sJmzNxZCgmjaLLzhsFk3dcYl7g4LXO8gx8XTbvo6L5t8R/vm7mfhleJCLgmYN//HR+5mWovJ1EefpWFjrOYHSjYdQ==" Dec 06 03:39:47 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:47-05:00" level=debug msg="connected to ap-gue1.spotify.com:4070" Dec 06 03:39:48 gbvpi-bedroom volumio[12451]: info: Initializing connection to go-librespot Websocket Dec 06 03:39:48 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:48-05:00" level=debug msg="new websocket client" Dec 06 03:39:48 gbvpi-bedroom volumio[12451]: info: Connection to go-librespot Websocket established Dec 06 03:39:50 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:50 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: info: Getting Spotify volume Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: 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 06 03:39:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: SPOTIFY: RECEIVED VOLUMIO VOLUME 91 Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: SPOTIFY: SPOTIFY VOLUME undefined Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: SPOTIFY: VOLUMIO VOLUME 91 Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: info: Aligning Spotify Volume to Volumio Volume Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: info: CoreCommandRouter::volumioGetState Dec 06 03:39:51 gbvpi-bedroom volumio[12451]: info: Setting Spotify Volume from Volumio: 91 Dec 06 03:39:52 gbvpi-bedroom volumio[12451]: SPOTIFY: SETTING SPOTIFY VOLUME 91 Dec 06 03:39:52 gbvpi-bedroom volumio[12451]: info: Sending Spotify command with payload to local API: /player/volume Dec 06 03:39:56 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:56-05:00" level=debug msg="completed keyexchange" Dec 06 03:39:56 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:56-05:00" level=debug msg="completed challenge" Dec 06 03:39:56 gbvpi-bedroom go-librespot[13184]: time="2025-12-06T03:39:56-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 06 03:39:56 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 06 03:39:56 gbvpi-bedroom systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: Error: socket hang up Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: at connResetException (node:internal/errors:720:14) Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: at Socket.emit (node:events:526:35) Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: code: 'ECONNRESET', Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: response: undefined Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: } Dec 06 03:39:56 gbvpi-bedroom volumio[12451]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 06 03:39:56 gbvpi-bedroom sudo[13220]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-06 03:38' Dec 06 03:39:56 gbvpi-bedroom sudo[13220]: 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="3a3cfe435f8bb2bc94a920662e91a4ef35bc8e7c" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="8bcc10c3dbcbcb349e9887dc0527d54876b32688" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Dec 2 11:51:19 UTC 2025" VOLUMIO_VERSION="4.072" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e5001581b220b096097cf8f46a54d4f1"