Dec 10 09:29:00 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:00 volumio go-librespot[27147]: go-librespot daemon starting...
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="app state loaded"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=info msg="zeroconf server listening on port 33117"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="obtained new client token: AACg/oY4qM6VjYKS6Ji3HGfR+0sWH63AgWhuFdCoBWuX875/rjY9l27cNUqbQ/H7uU1SFkpAlwEwlGRHfe1you8GBSCjkx6iUFRtHMV1FwmeeLCPcR/sQAewFfxeyYSozmJwpH5hgQNUU4ujo2SxO5H9JQ5HR3mUVMWUAo5XafzaiKRRfQ7+AvuoesFv40WHQISJJgqWOBUNqqn3KdCcL9j9TBkFTX7V9EWMupOQ/ZVSNM6sMhMeYcbdLQ=="
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=debug msg="completed challenge"
Dec 10 09:29:00 volumio go-librespot[27148]: time="2025-12-10T09:29:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:01 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:01 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36.
Dec 10 09:29:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:03 volumio go-librespot[27156]: go-librespot daemon starting...
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=debug msg="app state loaded"
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:29:03 volumio go-librespot[27157]: time="2025-12-10T09:29:03-06:00" level=info msg="zeroconf server listening on port 34809"
Dec 10 09:29:04 volumio go-librespot[27157]: time="2025-12-10T09:29:04-06:00" level=debug msg="obtained new client token: AACcTrCfNjkMo2Gk+1J1zZdgo6BWqksG06zrb86bXYd48PxE+OTOKYqx+snq1RPokqV+HK3Oh+rSnWrO6pKFPk3Cn+9JxKZKaK17e4pQnge3iJphGDPEDKmgxzPf+NTHArJfcw6Dix4lGgbHIODAPSWGImrVS76Y2VRaTZ95y/Ojv+AoxHlSKl2dmcoNhk6Y+Qlml3PiuhwMom+HQ64YcquLgZ7jOVdiIc6oqo/AU6ECRvlgkr5rGhI="
Dec 10 09:29:04 volumio go-librespot[27157]: time="2025-12-10T09:29:04-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:04 volumio go-librespot[27157]: time="2025-12-10T09:29:04-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:04 volumio go-librespot[27157]: time="2025-12-10T09:29:04-06:00" level=debug msg="completed challenge"
Dec 10 09:29:04 volumio go-librespot[27157]: time="2025-12-10T09:29:04-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 10 09:29:04 volumio volumio[26694]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 10 09:29:04 volumio volumio[26694]: info: Adding plugin multiroom to MyMusic Plugins
Dec 10 09:29:04 volumio volumio[26694]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 10 09:29:04 volumio volumio[26694]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 10 09:29:04 volumio volumio[26694]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 10 09:29:04 volumio volumio[26694]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 10 09:29:04 volumio volumio[26694]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 10 09:29:04 volumio volumio[26694]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 10 09:29:05 volumio volumio[26694]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 10 09:29:05 volumio volumio[26694]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 10 09:29:05 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:05 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:05 volumio volumio[26694]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 10 09:29:05 volumio volumio[26694]: info: MyVolumio login type: Token
Dec 10 09:29:05 volumio volumio[26694]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 10 09:29:05 volumio volumio[26694]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 10 09:29:06 volumio volumio[26694]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 10 09:29:06 volumio volumio[26694]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 10 09:29:06 volumio volumio[26694]: info: Streaming services startup
Dec 10 09:29:06 volumio volumio[26694]: info: Starting Streaming Daemon
Dec 10 09:29:06 volumio sudo[27179]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 10 09:29:06 volumio sudo[27179]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:06 volumio volumio[26694]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 10 09:29:06 volumio sudo[27179]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:06 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:06 volumio volumio[26694]: error: Cannot start Volumio Streaming Daemon
Dec 10 09:29:06 volumio volumio[26694]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 10 09:29:06 volumio volumio[26694]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 10 09:29:06 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:06 volumio volumio[26694]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 10 09:29:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37.
Dec 10 09:29:07 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:07 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:07 volumio go-librespot[27187]: go-librespot daemon starting...
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="app state loaded"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=info msg="zeroconf server listening on port 45651"
Dec 10 09:29:07 volumio volumio[26694]: info: MyVolumio token set successfully
Dec 10 09:29:07 volumio volumio[26694]: info: MYVOLUMIO: Adding device
Dec 10 09:29:07 volumio volumio[26694]: info: MYVOLUMIO: Evaluating Server
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="obtained new client token: AADVPXx37sIpzdbQS0QY95o2/YPt++P2yrXd2D1cu9LtZpZ/yFTs9bHsoXIO5coNlY8/4o3rh/y+RHR8TOUFMJom2tKZZR8EC6KI+EiDDH6UTDocBUMg/r9R9EI9aH2+w82xyENJXp2R+xlKOkANMUUj2ePk97eq2BqY+io/JqsSam2qfrHwoN9lA5HrPKnZo6/11zJA2OZguBzRfWZix9k76pjV/5XmLgsG1LzuDwAflBVtN0a2GdWoKQ=="
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:07 volumio go-librespot[27188]: time="2025-12-10T09:29:07-06:00" level=debug msg="completed challenge"
Dec 10 09:29:08 volumio go-librespot[27188]: time="2025-12-10T09:29:08-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:08 volumio volumio[26694]: info: MyVolumio status changed
Dec 10 09:29:08 volumio volumio[26694]: info: Streaming services startup
Dec 10 09:29:08 volumio volumio[26694]: info: Starting Streaming Daemon
Dec 10 09:29:08 volumio volumio[26694]: info: Removing browser output: myVolumio user plan is not superstar
Dec 10 09:29:08 volumio volumio[26694]: info: Removing audio output:
Dec 10 09:29:08 volumio volumio[26694]: info: Stoppping Tunnel 1
Dec 10 09:29:08 volumio sudo[27214]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 10 09:29:08 volumio sudo[27214]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:08 volumio sudo[27216]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 10 09:29:08 volumio sudo[27216]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio sudo[27214]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:08 volumio volumio[26694]: error: Cannot start Volumio Streaming Daemon
Dec 10 09:29:08 volumio volumio[26694]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 10 09:29:08 volumio volumio[26694]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:08 volumio sudo[27216]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:08 volumio volumio[26694]: info: Remote SSH Stopped
Dec 10 09:29:08 volumio volumio[26694]: info: Setting Geolocation for MyVolumio to us1
Dec 10 09:29:08 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:08 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:08 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:09 volumio volumio[26694]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 10 09:29:09 volumio volumio[26694]: info: Updating MyVolumio device info
Dec 10 09:29:09 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:09 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:09 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:09 volumio volumio[26694]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 10 09:29:09 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:09 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38.
Dec 10 09:29:11 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:11 volumio go-librespot[27219]: go-librespot daemon starting...
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="app state loaded"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=info msg="zeroconf server listening on port 42123"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="obtained new client token: AAAdosSsYfor/Gb/sDWARSBm3ryLuI5dzi8Kr74A0+lUB52Aqczq5C4XfnJQUKSv7d1eIu3FoYC23w7rz3moqWcBi02Lk4cdtgF9zKCcB0Jri9viMCvTaclVlj8+UUJ6uls7xs4SnL9B4NfOPWnC1KHdrukC6hWqiN6suecegu6MUhULMxUnv8PlWk0hpw9gCDBHEJHH7iQquOTD7UW+kSTgsOyERh//gX/ELxJ1Z8ljnKazu42Atxh7tw=="
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=debug msg="completed challenge"
Dec 10 09:29:11 volumio go-librespot[27220]: time="2025-12-10T09:29:11-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:12 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:12 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:13 volumio volumio[26694]: info: MYVOLUMIO: Adding device
Dec 10 09:29:13 volumio volumio[26694]: info: MYVOLUMIO: Evaluating Server
Dec 10 09:29:13 volumio volumio[26694]: info: Setting Geolocation for MyVolumio to us1
Dec 10 09:29:13 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:13 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:13 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:14 volumio volumio[26694]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 10 09:29:14 volumio volumio[26694]: info: Updating MyVolumio device info
Dec 10 09:29:14 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:14 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:14 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:14 volumio volumio[26694]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 10 09:29:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39.
Dec 10 09:29:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:15 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:15 volumio go-librespot[27245]: go-librespot daemon starting...
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="app state loaded"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=info msg="zeroconf server listening on port 43109"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="obtained new client token: AAD1cEdpw5JzNFwevrdHGM4GnejTpLNAG/uImaw1Ctx/SMuEA8x3ooaY5J2dJiFZOzQZ0KTG0BCB9pjHIt1PNv8v/HSDuQ5En+A7s0lhibrNzgvUdO8QnCZjYC57La0rXQD5NC8iwXR6layu8P2A455ukE5PG9z/fdsvF2q9KXxoxCvOWi8XzuxC/G+Xcrx0j28IVrEKXoh8MIfgye7wB1h0YlxY6dhDKGIH6xUNigk0SV/Cj2M6hRjf0Q=="
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=debug msg="completed challenge"
Dec 10 09:29:15 volumio go-librespot[27246]: time="2025-12-10T09:29:15-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:15 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:15 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:18 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:29:18 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:18 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 10 09:29:18 volumio volumio-remote-updater[9752]: Test mode disabled
Dec 10 09:29:18 volumio volumio-remote-updater[9752]: Alpha mode disabled
Dec 10 09:29:18 volumio volumio-remote-updater[9752]: Alpha legacy test mode disabled
Dec 10 09:29:18 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Dec 10 09:29:18 volumio volumio[26694]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"ANNOUNCEMENT
\n\n- Production line
\n
\nFIX
\n\n- Nodejs 20.5.1 version pinning with static package fallback
\n
\n","title":"Update v4.073","updateavailable":true}
Dec 10 09:29:18 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Dec 10 09:29:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40.
Dec 10 09:29:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:18 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:18 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:18 volumio go-librespot[27275]: go-librespot daemon starting...
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=debug msg="app state loaded"
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:18 volumio go-librespot[27276]: time="2025-12-10T09:29:18-06:00" level=info msg="zeroconf server listening on port 41115"
Dec 10 09:29:19 volumio go-librespot[27276]: time="2025-12-10T09:29:19-06:00" level=debug msg="obtained new client token: AABzz1POuiSX0cLEL+1GZaHcc6IdDoWKdUO7UNFf8+ap4jsREOobooDPPxrxgyphMfNj6n9/y+RKOsg1aI6VHrZNFXte9akbfNPJ2HE3dYCRFDa80w42tRL0U7TxHAqknCWT8+itq/rvAaN2BYoa+rT1lATXBfB6KWxtZ7jSwnJoPuzCPBfS8OGmdcjYewYf3Zm+R4myhme6IZVU+CvKfu8rdYP58ZTrPcbd8TB1UJYDbaO/kUUqMzo="
Dec 10 09:29:19 volumio go-librespot[27276]: time="2025-12-10T09:29:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:19 volumio go-librespot[27276]: time="2025-12-10T09:29:19-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:19 volumio go-librespot[27276]: time="2025-12-10T09:29:19-06:00" level=debug msg="completed challenge"
Dec 10 09:29:19 volumio go-librespot[27276]: time="2025-12-10T09:29:19-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:20 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 10 09:29:20 volumio volumio[26694]: 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 10 09:29:20 volumio volumio[26694]: info: CoreCommandRouter::volumioGetState
Dec 10 09:29:20 volumio volumio[26694]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:21 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:21 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41.
Dec 10 09:29:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:22 volumio go-librespot[27283]: go-librespot daemon starting...
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="app state loaded"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=info msg="zeroconf server listening on port 34205"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="obtained new client token: AADWHtMdfD5wBcgiJRlyVoBApryatYBtaATMOzh0c3+JvpuXRe1pmYGkFjIVjbAG16mpLZW2aaCwU2UvkTZAJYKDu5wCCRF+DlTRyaaXZQI57RfNfmFAYyR62eFASsQLQktZq59f6tGgwLsyFI2a6RhIMUhANNgHgXZQ6WlcrynH7Fd1O4UhiEbgM80OkMqs+uEuRYqNChlYDdY46yTxrU0MgEOdg+Wv+EWurk2MFbBz0yIQOSiEivvjAQ=="
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:22 volumio go-librespot[27284]: time="2025-12-10T09:29:22-06:00" level=debug msg="completed challenge"
Dec 10 09:29:23 volumio go-librespot[27284]: time="2025-12-10T09:29:23-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:24 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:24 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:25 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:25 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:25 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Dec 10 09:29:25 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Dec 10 09:29:25 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Dec 10 09:29:25 volumio volumio[26694]: info: CoreCommandRouter::volumioGetBrowseSources
Dec 10 09:29:25 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:29:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42.
Dec 10 09:29:26 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:26 volumio go-librespot[27305]: go-librespot daemon starting...
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="app state loaded"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=info msg="zeroconf server listening on port 37387"
Dec 10 09:29:26 volumio volumio[26694]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Dec 10 09:29:26 volumio volumio[26694]: info: Completed starting MyVolumio Plugin
Dec 10 09:29:26 volumio volumio[26694]: [Metrics] CommandRouter: 53s 925.58ms
Dec 10 09:29:26 volumio volumio[26694]: info: CoreCommandRouter::volumiosetStartupVolume
Dec 10 09:29:26 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:26 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:26 volumio volumio[26694]: info: CoreCommandRouter::Close All Modals sent
Dec 10 09:29:26 volumio volumio[26694]: info: CoreCommandRouter::Close All Modals sent
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="obtained new client token: AADTDa630KlwBRzPB/QCwnwTWLW0uH+eBDAKUwomZLJwP5csotJncLkiOvzqgGZODFIgfWaWngVWuBeepNhbBn9rSX+tHE8VeYtxBvvTAHPKOkvuf4VuapoTjTGzGcPMqDLEtCfzyNPKzapX91JFePOrwZBnuRh5XnUb1OU+bl5Eeq4UtoM/KFPnM/JcZn9rzMyWWBHPP8C8/waVR46Iit1cstd3IyAHCpYTW4/pXvqiPexLairgFhwSdg=="
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=debug msg="completed challenge"
Dec 10 09:29:26 volumio go-librespot[27306]: time="2025-12-10T09:29:26-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:27 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Dec 10 09:29:27 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Dec 10 09:29:27 volumio volumio[26694]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Dec 10 09:29:27 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:27 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 43.
Dec 10 09:29:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:29 volumio go-librespot[27320]: go-librespot daemon starting...
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="app state loaded"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=info msg="zeroconf server listening on port 37933"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="obtained new client token: AADRKz6vbB0DMHSHbYOo7X0wvPekBQBk+X91fkGYLLILwSS9Lx9jOhrahANS94pMVDvEr4+RAqnpiNoKrKkq+aI8Jsqx0JTOsUtj1nd5DKZBjY8T6OvdSNXGih/T59K8x3z89izHCdQJXH3ajSovgrh/XWO1E7ukfiOAyK8t2iRqAHPQBxGLV6fatuMQ6/Mel4AR0ixn9J0zECfzdl0NhsbzzDLyw3UVzODwo/A6UrSUPUgV/IKSg2YN0g=="
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=debug msg="completed challenge"
Dec 10 09:29:30 volumio go-librespot[27321]: time="2025-12-10T09:29:30-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:30 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:30 volumio volumio[26694]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:33 volumio volumio[26694]: info: BOOT COMPLETED
Dec 10 09:29:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44.
Dec 10 09:29:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:33 volumio go-librespot[27328]: go-librespot daemon starting...
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=debug msg="app state loaded"
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:33 volumio volumio[26694]: info: Initializing connection to go-librespot Websocket
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=debug msg="new websocket client"
Dec 10 09:29:33 volumio volumio[26694]: info: Connection to go-librespot Websocket established
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:29:33 volumio go-librespot[27329]: time="2025-12-10T09:29:33-06:00" level=info msg="zeroconf server listening on port 39181"
Dec 10 09:29:34 volumio go-librespot[27329]: time="2025-12-10T09:29:34-06:00" level=debug msg="obtained new client token: AAAU2ded8aXV6SGg+znmY4ezliQBE3G77UCAd9LPmYGcBQDwWRBd/dAae3PPT7VEq5WgipfgPM/uMGnkdAhOukmbJ/xSj3bKgfadHWihP+n66kOI5b+Uo1+v5Y+B/qQap2QFpxXYEPuvpAUhscQFY8WFg3AYk40Ng8zdt4XXlg8AS57juAcber6V9v9ycsTKZpT5KEidCCT6p97z/iPwrTNIYQ7UPI6DzgqXH94XOrgfJatUAQ1RF34="
Dec 10 09:29:34 volumio go-librespot[27329]: time="2025-12-10T09:29:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:34 volumio go-librespot[27329]: time="2025-12-10T09:29:34-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:34 volumio go-librespot[27329]: time="2025-12-10T09:29:34-06:00" level=debug msg="completed challenge"
Dec 10 09:29:34 volumio go-librespot[27329]: time="2025-12-10T09:29:34-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:34 volumio volumio[26694]: info: Connection to go-librespot Websocket closed
Dec 10 09:29:36 volumio volumio[26694]: info: Getting Spotify volume
Dec 10 09:29:36 volumio volumio[26694]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 10 09:29:36 volumio volumio[26694]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:29:36 volumio volumio[26694]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 10 09:29:36 volumio volumio[26694]: errno: -111,
Dec 10 09:29:36 volumio volumio[26694]: code: 'ECONNREFUSED',
Dec 10 09:29:36 volumio volumio[26694]: syscall: 'connect',
Dec 10 09:29:36 volumio volumio[26694]: address: '127.0.0.1',
Dec 10 09:29:36 volumio volumio[26694]: port: 9879,
Dec 10 09:29:36 volumio volumio[26694]: response: undefined
Dec 10 09:29:36 volumio volumio[26694]: }
Dec 10 09:29:36 volumio volumio[26694]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 10 09:29:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 45.
Dec 10 09:29:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:37 volumio go-librespot[27366]: go-librespot daemon starting...
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="app state loaded"
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:37 volumio sudo[27375]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-10 09:28'
Dec 10 09:29:37 volumio sudo[27375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=info msg="zeroconf server listening on port 40059"
Dec 10 09:29:37 volumio sudo[27375]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="obtained new client token: AABCtVvtBJ58cwQUuX/8Ld49n1ssGHyE1sMSD0Ooi5lST5qxdiJNNzM+pJ36qDbXG4hOs2lLxlrhhxdnIs1cSEBmkThv7hhTefn7vDRP5Rw0ATh+W6KQk9yWZQ7OWN/Ngd7cbV+vR02lqkZ9v4vM8P1A9gAuW+vzJoahlU22mR06POMO8pkQzj6NYlodvObZ0YxcEqcNBgyoLlErzDVIlW8iDOr9iqKoRCf1gsqcpwepbDaEW/bfpN5yBQ=="
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:37 volumio volumio-remote-updater[9752]: [2025-12-10 09:29:37] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 10 09:29:37 volumio volumio-remote-updater[9752]: [2025-12-10 09:29:37] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 10 09:29:37 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:37 volumio go-librespot[27367]: time="2025-12-10T09:29:37-06:00" level=debug msg="completed challenge"
Dec 10 09:29:37 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 10 09:29:37 volumio systemd[1]: volumio.service: Consumed 50.779s CPU time.
Dec 10 09:29:38 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 10 09:29:38 volumio go-librespot[27367]: time="2025-12-10T09:29:38-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:38 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 10 09:29:38 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 25345.
Dec 10 09:29:38 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 10 09:29:38 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 10 09:29:38 volumio systemd[1]: volumio.service: Consumed 50.779s CPU time.
Dec 10 09:29:38 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 10 09:29:38 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 10 09:29:40 volumio volumio[27390]: info: -------------------------------------------
Dec 10 09:29:40 volumio volumio[27390]: info: ----- Volumio3 ----
Dec 10 09:29:40 volumio volumio[27390]: info: -------------------------------------------
Dec 10 09:29:40 volumio volumio[27390]: info: ----- System startup ----
Dec 10 09:29:40 volumio volumio[27390]: info: -------------------------------------------
Dec 10 09:29:40 volumio volumio[27390]: info: MYVOLUMIO Environment detected
Dec 10 09:29:41 volumio volumio[27390]: info: Plugin folders cleanup
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning into folder /volumio/app/plugins/
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category audio_interface
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category miscellanea
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category music_service
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category plugins.json
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category system_controller
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category user_interface
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning into folder /data/plugins/
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category audio_interface
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category music_service
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category system_controller
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category system_hardware
Dec 10 09:29:41 volumio volumio[27390]: info: Scanning category user_interface
Dec 10 09:29:41 volumio volumio[27390]: info: Plugin folders cleanup completed
Dec 10 09:29:41 volumio volumio[27390]: info: -------------------------------------------
Dec 10 09:29:41 volumio volumio[27390]: info: ----- Core plugins startup ----
Dec 10 09:29:41 volumio volumio[27390]: info: -------------------------------------------
Dec 10 09:29:41 volumio volumio[27390]: info: Loading plugins from folder /volumio/app/plugins/
Dec 10 09:29:41 volumio volumio[27390]: info: Adding plugin upnp to MyMusic Plugins
Dec 10 09:29:41 volumio volumio[27390]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 10 09:29:41 volumio volumio[27390]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 10 09:29:41 volumio volumio[27390]: info: Loading plugins from folder /data/plugins/
Dec 10 09:29:41 volumio volumio[27390]: info: Loading plugin "system"...
Dec 10 09:29:41 volumio volumio[27390]: info: Loading plugin "appearance"...
Dec 10 09:29:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46.
Dec 10 09:29:41 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:41 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:41 volumio go-librespot[27417]: go-librespot daemon starting...
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=debug msg="app state loaded"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=info msg="zeroconf server listening on port 33073"
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=debug msg="obtained new client token: AAB+ElKXCJmv9s8IxV50cJ+26EY5R3ajWpESwRiyAy+m5w3k7C8/6j0/t9g/fgkWGtrvTfCIBmmujkEo0WAYToVuegCWD49Iu2T/FFDSuoDabGMkhfDI86vZVpJi9oaNUU/FRnsa/vhENxuumuuOU4awxU8fPVRJYd/BTLDhUbZraxZkafd1HYuP9iDmxDLfh05vXPDrrC3E20BKp+bxZviOJo/gM6U5ZXWJEB30idboGpxKptvZdyyFNQ=="
Dec 10 09:29:41 volumio go-librespot[27418]: time="2025-12-10T09:29:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "network"...
Dec 10 09:29:42 volumio volumio[27390]: info: Refreshing Cached IP Addresses
Dec 10 09:29:42 volumio sudo[27426]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 10 09:29:42 volumio sudo[27426]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:42 volumio sudo[27428]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 10 09:29:42 volumio sudo[27428]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "services"...
Dec 10 09:29:42 volumio sudo[27426]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "alsa_controller"...
Dec 10 09:29:42 volumio sudo[27428]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:42 volumio sudo[27435]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 10 09:29:42 volumio sudo[27435]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:42 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "wizard"...
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "networkfs"...
Dec 10 09:29:42 volumio volumio[27390]: info: Starting Udev Watcher for removable devices
Dec 10 09:29:42 volumio volumio[27390]: info: Ignoring mount for partition: boot
Dec 10 09:29:42 volumio volumio[27390]: info: Ignoring mount for partition: volumio
Dec 10 09:29:42 volumio volumio[27390]: info: Ignoring mount for partition: volumio_data
Dec 10 09:29:42 volumio volumio[27390]: info: Mounting Device Wikipedia
Dec 10 09:29:42 volumio sudo[27465]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 10 09:29:42 volumio sudo[27465]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:42 volumio sudo[27465]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:42 volumio volumio[27390]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 10 09:29:42 volumio volumio[27390]: dmesg(1) may have more information after failed mount system call.
Dec 10 09:29:42 volumio volumio[27390]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 10 09:29:42 volumio volumio[27390]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 10 09:29:42 volumio volumio[27390]: dmesg(1) may have more information after failed mount system call.
Dec 10 09:29:42 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "volumio_command_line_client"...
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "upnp"...
Dec 10 09:29:42 volumio volumio[27390]: info: [1765380582545] Starting Upmpd Daemon
Dec 10 09:29:42 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "my_music"...
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "mpd"...
Dec 10 09:29:42 volumio go-librespot[27418]: time="2025-12-10T09:29:42-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:42 volumio go-librespot[27418]: time="2025-12-10T09:29:42-06:00" level=debug msg="completed challenge"
Dec 10 09:29:42 volumio sudo[27435]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:42 volumio volumio[27390]: info: Loading plugin "upnp_browser"...
Dec 10 09:29:42 volumio go-librespot[27418]: time="2025-12-10T09:29:42-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:42 volumio volumio-remote-updater[9752]: [2025-12-10 09:29:42] [connect] Successful connection
Dec 10 09:29:44 volumio volumio[27390]: info: Loading plugin "alarm-clock"...
Dec 10 09:29:44 volumio volumio[27390]: info: Loading plugin "airplay_emulation"...
Dec 10 09:29:44 volumio volumio[27390]: info: Starting Shairport Sync
Dec 10 09:29:44 volumio volumio[27390]: info: Loading plugin "last_100"...
Dec 10 09:29:44 volumio volumio[27390]: info: Loading plugin "webradio"...
Dec 10 09:29:44 volumio volumio[27390]: info: Loading plugin "i2s_dacs"...
Dec 10 09:29:44 volumio volumio[27390]: info: I2S DAC not set, start Auto-detection
Dec 10 09:29:44 volumio volumio[27390]: info: Loading plugin "volumiodiscovery"...
Dec 10 09:29:44 volumio volumio[27390]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:29:44 volumio volumio[27390]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:29:44 volumio volumio[27390]: *** WARNING *** For more information see
Dec 10 09:29:44 volumio volumio[27390]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:29:44 volumio volumio[27390]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:29:44 volumio volumio[27390]: *** WARNING *** For more information see
Dec 10 09:29:44 volumio node[27390]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:29:44 volumio node[27390]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:29:44 volumio node[27390]: *** WARNING *** For more information see
Dec 10 09:29:44 volumio node[27390]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:29:44 volumio node[27390]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:29:44 volumio node[27390]: *** WARNING *** For more information see
Dec 10 09:29:44 volumio volumio[27390]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 10 09:29:44 volumio volumio[27390]: info: Discovery: Started advertising with name: Volumio
Dec 10 09:29:44 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 10 09:29:44 volumio volumio[27390]: info: Loading plugin "bandcamp"...
Dec 10 09:29:46 volumio volumio[27390]: info: Plugin calmradio is not enabled
Dec 10 09:29:46 volumio volumio[27390]: info: Loading plugin "soundcloud"...
Dec 10 09:29:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 47.
Dec 10 09:29:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:46 volumio go-librespot[27470]: go-librespot daemon starting...
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="app state loaded"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:46 volumio volumio[27390]: info: Loading plugin "spop"...
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=info msg="zeroconf server listening on port 45771"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="obtained new client token: AACd7rDbkFMgOmm6ztYrVN0e/oC6eKjJ9CSuHMHhhDkc1d0FYxXMXtvLc0H/JyJ557EpBvdfwg0K6lYG5x2H0rR39PnLoWoRwXvkZU/QhozdnR1//J6udfaJFzx+KdyqbHmvn4tvwmfhClRQJQssQbO6FxPJt1WjiimRNHbVMsljiy4kHGvB5Z6wfBJrgeP3zuZF1/vOrn+IRAnj4lU9PrLqOwrDgIVGEqHZAqu0jmUzeP8DS47tnN9LKw=="
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=debug msg="completed challenge"
Dec 10 09:29:46 volumio go-librespot[27471]: time="2025-12-10T09:29:46-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:47 volumio volumio[27390]: info: Loading plugin "squeezelite_mc"...
Dec 10 09:29:48 volumio volumio[27390]: info: Loading plugin "youtube2"...
Dec 10 09:29:48 volumio volumio[27390]: info: Loading plugin "ytcr"...
Dec 10 09:29:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48.
Dec 10 09:29:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:50 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:50 volumio go-librespot[27478]: go-librespot daemon starting...
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="app state loaded"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "ytmusic"...
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=info msg="zeroconf server listening on port 44509"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="obtained new client token: AADMSUmwhFSNE9D3YQsmwqXfyd1tP8Ijv78cpz0JoDy+NNpAtB+tGVLeGaDp3/iSdeEzLTAjWW+Mbv4V96BkYPNtKF+yXg1xEKHyoT64w5W0t8/DlcE1/Zn5IpAXvXo9r2+K9/OhYkhLVWWisrb4GpOKLOY/5aK1z1YfCCk5BtY7+d53Wq7cbbxjejgmIbYfPMdOXkTlN/74qeHtYKN09xvAoFq6yhWz+0GV6Mzv/YXtSMyDuZ+R7A4F1w=="
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=debug msg="completed challenge"
Dec 10 09:29:50 volumio go-librespot[27479]: time="2025-12-10T09:29:50-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:50 volumio volumio[27390]: info: Plugin now_playing is not enabled
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "outputs"...
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "albumart"...
Dec 10 09:29:50 volumio volumio[27390]: info: Plugin example_plugin is not enabled
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "inputs"...
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "updater_comm"...
Dec 10 09:29:50 volumio volumio[27390]: info: Plugin mpdemulation is not enabled
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "rest_api"...
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "websocket"...
Dec 10 09:29:50 volumio volumio[27390]: info: Starting Socket.io Server version 1.7.4
Dec 10 09:29:50 volumio volumio[27390]: info: Plugin fusiondsp is not enabled
Dec 10 09:29:50 volumio volumio[27390]: info: Plugin mpdoutput is not enabled
Dec 10 09:29:50 volumio volumio[27390]: info: Plugin RoonBridge is not enabled
Dec 10 09:29:50 volumio volumio[27390]: info: Loading plugin "podcast"...
Dec 10 09:29:51 volumio volumio[27390]: info: ControllerPodcast::constructor
Dec 10 09:29:51 volumio volumio[27390]: info: Loading plugin "volusonic"...
Dec 10 09:29:51 volumio volumio[27486]: Forking 3 albumart workers
Dec 10 09:29:52 volumio volumio[27390]: info: Applying required configuration parameters for plugin volusonic
Dec 10 09:29:52 volumio volumio[27390]: info: Loading plugin "backup_restore"...
Dec 10 09:29:52 volumio volumio[27497]: Starting albumart workers
Dec 10 09:29:52 volumio volumio[27498]: Starting albumart workers
Dec 10 09:29:52 volumio volumio[27496]: Starting albumart workers
Dec 10 09:29:52 volumio volumio[27390]: info: Applying required configuration parameters for plugin backup_restore
Dec 10 09:29:53 volumio volumio[27390]: info: Plugin rpi_eeprom_config is not enabled
Dec 10 09:29:53 volumio volumio[27390]: info: Plugin rpi_eeprom_updater is not enabled
Dec 10 09:29:53 volumio volumio[27390]: info: Loading plugin "scheduledrestart"...
Dec 10 09:29:53 volumio volumio[27390]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 10 09:29:53 volumio volumio[27390]: info: Plugin Bluetoothremote is not enabled
Dec 10 09:29:53 volumio volumio[27390]: info: Plugin music_services_shield is not enabled
Dec 10 09:29:53 volumio volumio[27390]: info: Loading plugin "Systeminfo"...
Dec 10 09:29:53 volumio volumio[27390]: info: Plugin peppymeterbasic is not enabled
Dec 10 09:29:53 volumio volumio[27390]: info: Loading plugin "peppyspectrum"...
Dec 10 09:29:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49.
Dec 10 09:29:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:53 volumio go-librespot[27552]: go-librespot daemon starting...
Dec 10 09:29:53 volumio go-librespot[27559]: time="2025-12-10T09:29:53-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:53 volumio go-librespot[27559]: time="2025-12-10T09:29:53-06:00" level=debug msg="app state loaded"
Dec 10 09:29:53 volumio go-librespot[27559]: time="2025-12-10T09:29:53-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:53 volumio go-librespot[27559]: time="2025-12-10T09:29:53-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=info msg="zeroconf server listening on port 38365"
Dec 10 09:29:54 volumio volumio[27390]: info: Loading i18n strings for locale en
Dec 10 09:29:54 volumio volumio[27390]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 10 09:29:54 volumio volumio[27390]: Updating browse sources language
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=debug msg="obtained new client token: AACzrufO6qEuxcd9TzRfv85sC6ClSTRncX3ZRrT35NduM/i9N8rvMTFlGOrct/kQuASuL5WfAC6qIQ68goUGD+SN0Z0PPTNmYuBjNTcWTQDw13L3EtB2dpjFTWh84cLmk+KCjRhNnkvjrSlqBrkgXh/tdUkHNXvLoX6qalraAmcLXHBfMrALVIgH/x0sqmgyFL2LUUX9O1v//8IMdU1VtmCjAw8yPk/TtbTB/9qcoJLhE9v+rj2E5Pw="
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::initPlayerControls
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: Express server listening on port 3000
Dec 10 09:29:54 volumio volumio[27390]: [Metrics] WebUI: 14s 565.84ms
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::resetVolumioState
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::getcurrentVolume
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioRetrievevolume
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=debug msg="completed challenge"
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:54 volumio go-librespot[27559]: time="2025-12-10T09:29:54-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:54 volumio sudo[27571]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 10 09:29:54 volumio sudo[27571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:54 volumio sudo[27571]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:54 volumio sudo[27573]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 10 09:29:54 volumio sudo[27573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:54 volumio sudo[27573]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:54 volumio volumio[27390]: info: Volumio Network Manager: Network status updated: 1
Dec 10 09:29:54 volumio volumio[27390]: info: VolumeController:: Volume=86 Mute =false
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::pushState
Dec 10 09:29:54 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioPushState
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::updateTrackBlock
Dec 10 09:29:54 volumio volumio[27390]: info: CorePlayQueue::getTrackBlock
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioRetrievevolume
Dec 10 09:29:54 volumio volumio[27390]: info: Reloading queue from file
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::setRepeat null single undefined
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::pushState
Dec 10 09:29:54 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioPushState
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::setRandom null
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::pushState
Dec 10 09:29:54 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioPushState
Dec 10 09:29:54 volumio volumio[27390]: info: Setting Device type: Raspberry PI
Dec 10 09:29:54 volumio volumio[27390]: info: VolumeController:: Volume=86 Mute =false
Dec 10 09:29:54 volumio volumio[27390]: info: CoreStateMachine::pushState
Dec 10 09:29:54 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioPushState
Dec 10 09:29:54 volumio volumio[27390]: info: Completed loading Core Plugins
Dec 10 09:29:54 volumio volumio[27390]: info: Preparing to generate the ALSA configuration file
Dec 10 09:29:54 volumio sudo[27587]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 10 09:29:54 volumio sudo[27587]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:54 volumio volumio[27390]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 10 09:29:54 volumio volumio[27390]: info: Reading ALSA contributions from plugins.
Dec 10 09:29:54 volumio volumio[27390]: info: Asound.conf file unchanged, so no further update is needed
Dec 10 09:29:54 volumio volumio[27390]: info: Output device has changed, restarting MPD
Dec 10 09:29:54 volumio sudo[27587]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:54 volumio volumio[27390]: info: Output device has changed, restarting Shairport Sync
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:54 volumio sudo[27590]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 10 09:29:54 volumio sudo[27590]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:54 volumio sudo[27592]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 10 09:29:54 volumio sudo[27592]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:54 volumio sudo[27590]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:54 volumio volumio[27390]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:29:54 volumio volumio[27390]: info: ___________ START PLUGINS ___________
Dec 10 09:29:54 volumio volumio[27390]: info: ControllerMpd::onStart: Initializing MPD
Dec 10 09:29:54 volumio volumio[27390]: info: Creating MPD Configuration file
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:54 volumio volumio[27390]: info: [1765380594798] CoreMusicLibrary::Adding element Media Servers
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:54 volumio sudo[27600]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 10 09:29:54 volumio sudo[27600]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:54 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 10 09:29:54 volumio sudo[27600]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:54 volumio sudo[27602]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 10 09:29:54 volumio sudo[27602]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:54 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 10 09:29:54 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 10 09:29:54 volumio systemd[1]: mpd.service: Consumed 4.587s CPU time.
Dec 10 09:29:54 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 10 09:29:54 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 10 09:29:54 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 10 09:29:54 volumio volumio[27390]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:54 volumio volumio[27390]: info: [1765380594923] CoreMusicLibrary::Adding element Last_100
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:54 volumio volumio[27390]: info: [1765380594928] CoreMusicLibrary::Adding element Webradio
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:29:54 volumio volumio[27390]: info: Initializing BBC Radios
Dec 10 09:29:54 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 10 09:29:54 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:29:54 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:55 volumio volumio[27390]: info: [1765380595007] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:55 volumio volumio[27390]: info: [1765380595019] CoreMusicLibrary::Adding element SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: info: Creating Spotify config file
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:55 volumio sudo[27624]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 10 09:29:55 volumio sudo[27624]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 10 09:29:55 volumio sudo[27624]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:55 volumio volumio[27390]: info: [squeezelite_mc] Starting proxy server...
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:55 volumio volumio[27390]: info: [1765380595373] CoreMusicLibrary::Adding element YouTube2
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube2
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:55 volumio volumio[27390]: info: [1765380595391] CoreMusicLibrary::Adding element YouTube Music
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube2
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube Music
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:55 volumio volumio[27390]: info: [1765380595403] CoreMusicLibrary::Adding element Podcast
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube2
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube Music
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Podcast
Dec 10 09:29:55 volumio volumio[27390]: info: Loading i18n strings for locale en
Dec 10 09:29:55 volumio volumio[27390]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 10 09:29:55 volumio volumio[27390]: Updating browse sources language
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube2
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube Music
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Podcast
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube2
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube Music
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Podcast
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:55 volumio volumio[27390]: info: [1765380595450] CoreMusicLibrary::Adding element Volusonic
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube2
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source YouTube Music
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Podcast
Dec 10 09:29:55 volumio volumio[27390]: Cannot find translation for source Volusonic
Dec 10 09:29:55 volumio volumio-remote-updater[9752]: [2025-12-10 09:29:55] [connect] Successful connection
Dec 10 09:29:55 volumio volumio[27390]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 10 09:29:55 volumio volumio[27390]: info: Volumio Calling Home
Dec 10 09:29:55 volumio volumio[27390]: info: [squeezelite_mc] Proxy server started on port 37415
Dec 10 09:29:55 volumio volumio[27390]: info: Preparing to generate the ALSA configuration file
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioRetrievevolume
Dec 10 09:29:55 volumio volumio[27390]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 10 09:29:55 volumio volumio[27390]: info: Discovery: Found device Volumio
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioGetState
Dec 10 09:29:55 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:55 volumio volumio[27390]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954
Dec 10 09:29:55 volumio volumio[27390]: info: Discovery: Found device Volumio
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioGetState
Dec 10 09:29:55 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:55 volumio volumio[27390]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 10 09:29:55 volumio volumio[27390]: info: Reading ALSA contributions from plugins.
Dec 10 09:29:55 volumio volumio[27390]: info: MPD Permissions set
Dec 10 09:29:55 volumio volumio[27390]: info: MPD Permissions set
Dec 10 09:29:55 volumio volumio[27390]: info: Upmpdcli Daemon Started
Dec 10 09:29:55 volumio volumio-remote-updater[9752]: [2025-12-10 09:29:55] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765380595 101
Dec 10 09:29:55 volumio volumio[27390]: 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 10 09:29:55 volumio volumio[27390]: info: Spotify config file written
Dec 10 09:29:55 volumio sudo[27637]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 10 09:29:55 volumio sudo[27637]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:55 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:55 volumio volumio[27390]: 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 10 09:29:55 volumio volumio[27390]: info: VolumeController:: Volume=86 Mute =false
Dec 10 09:29:55 volumio volumio[27390]: info: CoreStateMachine::pushState
Dec 10 09:29:55 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:55 volumio volumio[27390]: info: CoreCommandRouter::volumioPushState
Dec 10 09:29:55 volumio go-librespot[27639]: go-librespot daemon starting...
Dec 10 09:29:55 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:55 volumio volumio[27390]: info: [squeezelite_mc] Server discovery started
Dec 10 09:29:55 volumio volumio[27390]: info: [squeezelite_mc] Player finder started
Dec 10 09:29:55 volumio sudo[27637]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="app state loaded"
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: No need to fix Spotify hosts
Dec 10 09:29:56 volumio volumio[27390]: 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 10 09:29:56 volumio volumio[27390]: info: Volumio called home
Dec 10 09:29:56 volumio volumio[27390]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}
Dec 10 09:29:56 volumio volumio[27390]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 10 09:29:56 volumio volumio[27390]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 10 09:29:56 volumio volumio[27390]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=info msg="zeroconf server listening on port 36629"
Dec 10 09:29:56 volumio volumio[27390]: info: Starting Shairport Sync
Dec 10 09:29:56 volumio volumio[27390]: info: Starting Shairport Sync
Dec 10 09:29:56 volumio volumio[27390]: info: Starting Shairport Sync
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="obtained new client token: AADO2Ahp5pX9RLz5Y521jmK/dX4ZvnqGatCLUdNi4UJe9abG952hQZySdR93NK7aNxh15acqzDjpKiJLaOaqp8aagRovBePWWFp0Zwvi7YlKV46Z78cRa+QXHeEdBBk+ZgWNZDBvmI+zv1XAeiEfVyjaSgt+EhDmcqmu6tDZbIS2W9Irf2QetyvyoLfEgUyLQH/rNX6reyn8Cplwz/v+NBhbULisIOghxpLoBaYXjM7EkKCwRBNfxBAgMg=="
Dec 10 09:29:56 volumio sudo[27663]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:29:56 volumio sudo[27663]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:56 volumio sudo[27666]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:29:56 volumio sudo[27666]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:56 volumio sudo[27661]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 10 09:29:56 volumio sudo[27661]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:29:56 volumio sudo[27661]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:56 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 10 09:29:56 volumio volumio[27390]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 10 09:29:56 volumio volumio[27390]: SPOTIFY: BQB40CvJ6PdVIjKKgLGEN3d8wanT9XZmAJkrqH5TfGB7E_z7MQJxuwPBj8uo8e6SlRY4rK9WjvWNCnsh-G3D4yhpIAwKzdtBhM--8LjgQHM0jSHRYXGaj84HHGvM7AI6psIN_ZyyhCglL8H-pynaCW6uB8xlF0VTsDCDFoBpdsHT6hH2ySHKx8YGbvNBKEigk_pwYBLWnnXC0XEv9yftBo72o-TWbOJXXPIAdEw
Dec 10 09:29:56 volumio volumio[27390]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 10 09:29:56 volumio volumio[27390]: info: New Spotify access token = BQB40CvJ6PdVIjKKgLGEN3d8wanT9XZmAJkrqH5TfGB7E_z7MQJxuwPBj8uo8e6SlRY4rK9WjvWNCnsh-G3D4yhpIAwKzdtBhM--8LjgQHM0jSHRYXGaj84HHGvM7AI6psIN_ZyyhCglL8H-pynaCW6uB8xlF0VTsDCDFoBpdsHT6hH2ySHKx8YGbvNBKEigk_pwYBLWnnXC0XEv9yftBo72o-TWbOJXXPIAdEw
Dec 10 09:29:56 volumio volumio[27390]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 10 09:29:56 volumio sudo[27667]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:29:56 volumio sudo[27667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="completed keyexchange"
Dec 10 09:29:56 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 10 09:29:56 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:29:56 volumio systemd[1]: shairport-sync.service: Consumed 1.920s CPU time.
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=debug msg="completed challenge"
Dec 10 09:29:56 volumio volumio[27390]: info: Asound.conf file unchanged, so no further update is needed
Dec 10 09:29:56 volumio volumio[27390]: info: Output device has changed, restarting MPD
Dec 10 09:29:56 volumio go-librespot[27640]: time="2025-12-10T09:29:56-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:29:56 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:29:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:29:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:29:56 volumio sudo[27663]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:56 volumio volumio[27390]: info: Output device has changed, restarting Shairport Sync
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:56 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:56 volumio sudo[27674]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 10 09:29:56 volumio sudo[27674]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:56 volumio sudo[27666]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:56 volumio sudo[27674]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:56 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 10 09:29:56 volumio sudo[27676]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 10 09:29:56 volumio sudo[27676]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:56 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 10 09:29:56 volumio volumio[27390]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:29:56 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:29:56 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:29:56 volumio sudo[27667]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:56 volumio volumio[27390]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 10 09:29:56 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 10 09:29:56 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 10 09:29:56 volumio systemd[1]: mpd.service: Consumed 1.724s CPU time.
Dec 10 09:29:56 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 10 09:29:56 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 10 09:29:56 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 10 09:29:56 volumio sudo[27692]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 10 09:29:56 volumio sudo[27692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:56 volumio volumio[27390]: info: MPD Permissions set
Dec 10 09:29:56 volumio sudo[27692]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:56 volumio volumio[27390]: info: Shairport-Sync Started
Dec 10 09:29:56 volumio volumio[27390]: Error adding Membership: Error: addMembership EINVAL
Dec 10 09:29:56 volumio volumio[27390]: info: Shairport-Sync Started
Dec 10 09:29:56 volumio volumio[27390]: info: Shairport-Sync Started
Dec 10 09:29:56 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 10 09:29:56 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 10 09:29:56 volumio volumio[27390]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::volumioGetState
Dec 10 09:29:57 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:57 volumio volumio[27390]: info: Starting Shairport Sync
Dec 10 09:29:57 volumio sudo[27712]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 10 09:29:57 volumio sudo[27709]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 10 09:29:57 volumio sudo[27709]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 10 09:29:57 volumio sudo[27712]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:57 volumio sudo[27709]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:57 volumio sudo[27722]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:29:57 volumio sudo[27722]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:57 volumio sudo[27712]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:57 volumio volumio[27390]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"}
Dec 10 09:29:57 volumio volumio[27390]: info: Spotify Successfully logged in
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:29:57 volumio volumio[27390]: info: [1765380597293] CoreMusicLibrary::Adding element Spotify
Dec 10 09:29:57 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:29:57 volumio volumio[27390]: Cannot find translation for source Bandcamp Discover
Dec 10 09:29:57 volumio volumio[27390]: Cannot find translation for source SoundCloud
Dec 10 09:29:57 volumio volumio[27390]: Cannot find translation for source YouTube2
Dec 10 09:29:57 volumio volumio[27390]: Cannot find translation for source YouTube Music
Dec 10 09:29:57 volumio volumio[27390]: Cannot find translation for source Podcast
Dec 10 09:29:57 volumio volumio[27390]: Cannot find translation for source Volusonic
Dec 10 09:29:57 volumio volumio[27390]: Cannot find translation for source Spotify
Dec 10 09:29:57 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true
Dec 10 09:29:57 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 10 09:29:57 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 10 09:29:57 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:29:57 volumio sudo[27728]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 10 09:29:57 volumio sudo[27728]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:57 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:29:57 volumio sudo[27722]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:57 volumio systemd[1]: Reloading.
Dec 10 09:29:57 volumio volumio[27390]: info: Shairport-Sync Started
Dec 10 09:29:57 volumio volumio[27390]: info: [squeezelite_mc] Notification listener started
Dec 10 09:29:57 volumio volumio[27390]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 10 09:29:58 volumio volumio[27390]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 10 09:29:58 volumio volumio[27390]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 10 09:29:58 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:58 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:58 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:29:58 volumio volumio[27390]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:29:59 volumio volumio[27390]: info: go-librespot daemon successfully initialized
Dec 10 09:29:59 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:59 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:29:59 volumio sudo[27728]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:59 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:29:59 volumio sudo[27763]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:29:59 volumio sudo[27763]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:59 volumio volumio[27390]: info: CoreCommandRouter::volumioGetState
Dec 10 09:29:59 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:29:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50.
Dec 10 09:29:59 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:59 volumio sudo[27763]: pam_unix(sudo:session): session closed for user root
Dec 10 09:29:59 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 10 09:29:59 volumio sudo[27767]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 10 09:29:59 volumio sudo[27767]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:29:59 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:29:59 volumio go-librespot[27765]: go-librespot daemon starting...
Dec 10 09:29:59 volumio go-librespot[27769]: time="2025-12-10T09:29:59-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:29:59 volumio go-librespot[27769]: time="2025-12-10T09:29:59-06:00" level=debug msg="app state loaded"
Dec 10 09:29:59 volumio go-librespot[27769]: time="2025-12-10T09:29:59-06:00" level=debug msg="stored credentials not found"
Dec 10 09:29:59 volumio go-librespot[27769]: time="2025-12-10T09:29:59-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:29:59 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 10 09:29:59 volumio volumio[27390]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 10 09:29:59 volumio volumio[27390]: info: CoreCommandRouter::volumioGetState
Dec 10 09:29:59 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:00 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 10 09:30:00 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=info msg="zeroconf server listening on port 39227"
Dec 10 09:30:00 volumio sudo[27767]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=debug msg="obtained new client token: AACS3EVyYatMqi/XZUpI0G7pyc/rwypLozs9ya0l8WI9bzPnQ+uamzl1MmTW1H0l1RJCSavZsKSIXp3YPB96oR+5p4Xtfl/nujSSfMyRjkeqVzEsDyW1K6d17aB1DzEwRxo2xtkLdc7m+eT+3rNj0kY8IGCHFzPmNRMKNv8nEjsJ9vuirQvaSaQwT1xGMDzy0FklIszU3oLyRwuEGRTGnk+mAWqUA3qNprnsFlYlbqNnr05CPlLWsF8="
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=debug msg="completed challenge"
Dec 10 09:30:00 volumio go-librespot[27769]: time="2025-12-10T09:30:00-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:00 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:00 volumio sudo[27777]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:00 volumio sudo[27777]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:00 volumio sudo[27777]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:00 volumio volumio[27390]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 10 09:30:00 volumio sudo[27781]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 10 09:30:00 volumio sudo[27781]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:00 volumio sudo[27781]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:00 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 10 09:30:00 volumio sudo[27784]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 10 09:30:00 volumio sudo[27784]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:00 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 10 09:30:00 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 10 09:30:00 volumio sudo[27784]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:01 volumio mpd[27726]: 2025-12-10T09:30:01 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 10 09:30:01 volumio volumio[27390]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 10 09:30:01 volumio volumio[27390]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 10 09:30:01 volumio volumio[27390]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 10 09:30:01 volumio volumio[27390]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 10 09:30:01 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 10 09:30:01 volumio sudo[27592]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:01 volumio sudo[27676]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:01 volumio sudo[27602]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:01 volumio volumio[27390]: error: MPD error: The expression evaluated to a falsy value:
Dec 10 09:30:01 volumio volumio[27390]: assert.ok(self.idling)
Dec 10 09:30:01 volumio volumio[27390]: error: The expression evaluated to a falsy value:
Dec 10 09:30:01 volumio volumio[27390]: assert.ok(self.idling)
Dec 10 09:30:01 volumio volumio[27390]: error: MPD error: The expression evaluated to a falsy value:
Dec 10 09:30:01 volumio volumio[27390]: assert.ok(self.idling)
Dec 10 09:30:01 volumio volumio[27390]: error: The expression evaluated to a falsy value:
Dec 10 09:30:01 volumio volumio[27390]: assert.ok(self.idling)
Dec 10 09:30:01 volumio volumio[27390]: error: updateQueue error: null
Dec 10 09:30:01 volumio volumio[27390]: info: MPD running with PID27726
Dec 10 09:30:01 volumio volumio[27390]: ,establishing connection
Dec 10 09:30:01 volumio volumio[27390]: error: updateQueue error: null
Dec 10 09:30:01 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:01 volumio sudo[27796]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:01 volumio sudo[27796]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:01 volumio sudo[27796]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:02 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:02 volumio sudo[27799]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:02 volumio sudo[27799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:02 volumio sudo[27799]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:02 volumio volumio[27390]: info: CoreCommandRouter::volumioGetState
Dec 10 09:30:02 volumio volumio[27390]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:02 volumio volumio[27390]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:02 volumio volumio[27390]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:30:02 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:02 volumio sudo[27816]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:02 volumio sudo[27816]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:02 volumio sudo[27816]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:03 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:03 volumio sudo[27819]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:03 volumio sudo[27819]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:03 volumio sudo[27819]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 51.
Dec 10 09:30:03 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:03 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:03 volumio go-librespot[27821]: go-librespot daemon starting...
Dec 10 09:30:03 volumio go-librespot[27822]: time="2025-12-10T09:30:03-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:03 volumio go-librespot[27822]: time="2025-12-10T09:30:03-06:00" level=debug msg="app state loaded"
Dec 10 09:30:03 volumio go-librespot[27822]: time="2025-12-10T09:30:03-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:03 volumio go-librespot[27822]: time="2025-12-10T09:30:03-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:03 volumio volumio[27390]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:03 volumio sudo[27829]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:03 volumio sudo[27829]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:03 volumio sudo[27829]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:03 volumio volumio[27390]: info: Completed starting Core Plugins
Dec 10 09:30:03 volumio volumio[27390]: info: -------------------------------------------
Dec 10 09:30:03 volumio volumio[27390]: info: ----- MyVolumio plugins startup ----
Dec 10 09:30:03 volumio volumio[27390]: info: -------------------------------------------
Dec 10 09:30:03 volumio volumio[27390]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 10 09:30:04 volumio sudo[27834]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 10 09:30:04 volumio sudo[27834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:04 volumio sudo[27836]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 10 09:30:04 volumio sudo[27836]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:04 volumio sudo[27839]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 10 09:30:04 volumio sudo[27839]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:04 volumio go-librespot[27822]: time="2025-12-10T09:30:04-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:04 volumio go-librespot[27822]: time="2025-12-10T09:30:04-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:04 volumio go-librespot[27822]: time="2025-12-10T09:30:04-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:04 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 10 09:30:04 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 10 09:30:04 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 10 09:30:04 volumio go-librespot[27822]: time="2025-12-10T09:30:04-06:00" level=info msg="zeroconf server listening on port 40947"
Dec 10 09:30:04 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 10 09:30:04 volumio sudo[27834]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:04 volumio sudo[27839]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:04 volumio mpd_monitor.sh[27842]: MPD Monitor Service: Starting MPD Monitor Service
Dec 10 09:30:04 volumio sudo[27836]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:04 volumio volumio[27390]: info: Successfully started MPD Monitor
Dec 10 09:30:04 volumio volumio[27390]: info: Successfully started MPD Monitor
Dec 10 09:30:04 volumio volumio[27390]: info: Successfully started MPD Monitor
Dec 10 09:30:05 volumio go-librespot[27822]: time="2025-12-10T09:30:05-06:00" level=debug msg="obtained new client token: AADDEzK4MacmVLp3cnWhVUYZRIvL7/6+pWNo/fUjnBaeGwb3nVYUFzkHQaEI17HYRASqMXMiwKNq7+Dun11Badat30LKa3aFiiRNGCTARTzn8YEMnRrRXeSu2y0HVbei8frSpZt/FDJCXObFnGrOZENgHvoPzC2qP9nUyTH2N+jgua3dUnLBho8IJFLJkq3aUyHRso4MeHej1h4LFV9djKWoHbgikC4cZqCJUGSWXBtsurFjJdM2QMw="
Dec 10 09:30:05 volumio volumio[27390]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:05 volumio go-librespot[27822]: time="2025-12-10T09:30:05-06:00" level=debug msg="new websocket client"
Dec 10 09:30:05 volumio volumio[27390]: info: Connection to go-librespot Websocket established
Dec 10 09:30:05 volumio go-librespot[27822]: time="2025-12-10T09:30:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:05 volumio go-librespot[27822]: time="2025-12-10T09:30:05-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:05 volumio go-librespot[27822]: time="2025-12-10T09:30:05-06:00" level=debug msg="completed challenge"
Dec 10 09:30:05 volumio go-librespot[27822]: time="2025-12-10T09:30:05-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:05 volumio volumio[27390]: info: Connection to go-librespot Websocket closed
Dec 10 09:30:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 52.
Dec 10 09:30:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:08 volumio go-librespot[27846]: go-librespot daemon starting...
Dec 10 09:30:08 volumio go-librespot[27847]: time="2025-12-10T09:30:08-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:08 volumio go-librespot[27847]: time="2025-12-10T09:30:08-06:00" level=debug msg="app state loaded"
Dec 10 09:30:08 volumio go-librespot[27847]: time="2025-12-10T09:30:08-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:08 volumio go-librespot[27847]: time="2025-12-10T09:30:08-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=info msg="zeroconf server listening on port 36189"
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="obtained new client token: AACf4gEDxF98SQBsnCKmy91jadRp5D5okMmEEJyzdRgWwHB9WsfbaPHV50ysERmh088wqikaOFYTIrr5Orus7+V+8tPZcIqNLYbqMAgUnyC6gnzzvwU5iqYEQDqmP5V2/C/MbijN2jBKunaJXi3Ebwmn/EwHLb8kphkysI+FUxmE89VYPtFKeTlU5t4N/u1t+vzrE78D7OZEJTLwiWIsVj8PZ557s4/t6GeKab50xsCLf7etHnB52PU="
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:09 volumio volumio[27390]: info: Getting Spotify volume
Dec 10 09:30:09 volumio volumio[27390]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:09 volumio volumio[27390]: 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 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="new websocket client"
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=debug msg="completed challenge"
Dec 10 09:30:09 volumio volumio[27390]: info: Connection to go-librespot Websocket established
Dec 10 09:30:09 volumio go-librespot[27847]: time="2025-12-10T09:30:09-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:09 volumio volumio[27390]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 10 09:30:09 volumio volumio[27390]: Error: socket hang up
Dec 10 09:30:09 volumio volumio[27390]: at connResetException (node:internal/errors:720:14)
Dec 10 09:30:09 volumio volumio[27390]: at Socket.socketOnEnd (node:_http_client:519:23)
Dec 10 09:30:09 volumio volumio[27390]: at Socket.emit (node:events:526:35)
Dec 10 09:30:09 volumio volumio[27390]: at endReadableNT (node:internal/streams/readable:1376:12)
Dec 10 09:30:09 volumio volumio[27390]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
Dec 10 09:30:09 volumio volumio[27390]: code: 'ECONNRESET',
Dec 10 09:30:09 volumio volumio[27390]: response: undefined
Dec 10 09:30:09 volumio volumio[27390]: }
Dec 10 09:30:09 volumio volumio[27390]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 10 09:30:10 volumio sudo[27868]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-10 09:29'
Dec 10 09:30:10 volumio sudo[27868]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:10 volumio sudo[27868]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:11 volumio volumio-remote-updater[9752]: [2025-12-10 09:30:11] [error] handle_read_frame error: websocketpp.transport:7 (End of File)
Dec 10 09:30:11 volumio volumio-remote-updater[9752]: [2025-12-10 09:30:11] [disconnect] Disconnect close local:[1006,End of File] remote:[1006]
Dec 10 09:30:11 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:11 volumio systemd[1]: volumio.service: Failed with result 'exit-code'.
Dec 10 09:30:11 volumio systemd[1]: volumio.service: Consumed 43.331s CPU time.
Dec 10 09:30:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 10 09:30:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 10 09:30:11 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 25346.
Dec 10 09:30:11 volumio systemd[1]: Started dynamicswap.service - dynamicswap service.
Dec 10 09:30:11 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module.
Dec 10 09:30:11 volumio systemd[1]: volumio.service: Consumed 43.331s CPU time.
Dec 10 09:30:11 volumio systemd[1]: Started volumio.service - Volumio Backend Module.
Dec 10 09:30:11 volumio systemd[1]: dynamicswap.service: Deactivated successfully.
Dec 10 09:30:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 53.
Dec 10 09:30:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:12 volumio go-librespot[27898]: go-librespot daemon starting...
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=debug msg="app state loaded"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=info msg="zeroconf server listening on port 39035"
Dec 10 09:30:12 volumio go-librespot[27899]: time="2025-12-10T09:30:12-06:00" level=debug msg="obtained new client token: AACwxqKH/1d/s+7nuvJi3h/oGLMxCRIA/0af0Ck4GObpXSDaUqluGfLH5948UDXZXHw63GOlnghHwtt8XW+AvCms5nQ2GRAWZq1TcxWLec1qBaMShjUqo1gX53pblihNU8eAST+DyPHiFdunlPUzie6LlkXLhmvEKVNj2wLsYxZ76KPtHDptdyINan8/lA0wjZKMLlJHGSh95doVLa0pRZcQajbVOYbxusPqCOyjBk1W+t4iBcXKffqM/Q=="
Dec 10 09:30:13 volumio go-librespot[27899]: time="2025-12-10T09:30:13-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:13 volumio go-librespot[27899]: time="2025-12-10T09:30:13-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:13 volumio go-librespot[27899]: time="2025-12-10T09:30:13-06:00" level=debug msg="completed challenge"
Dec 10 09:30:13 volumio go-librespot[27899]: time="2025-12-10T09:30:13-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:13 volumio volumio[27883]: info: -------------------------------------------
Dec 10 09:30:13 volumio volumio[27883]: info: ----- Volumio3 ----
Dec 10 09:30:13 volumio volumio[27883]: info: -------------------------------------------
Dec 10 09:30:13 volumio volumio[27883]: info: ----- System startup ----
Dec 10 09:30:13 volumio volumio[27883]: info: -------------------------------------------
Dec 10 09:30:14 volumio volumio[27883]: info: MYVOLUMIO Environment detected
Dec 10 09:30:14 volumio volumio[27883]: info: Plugin folders cleanup
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning into folder /volumio/app/plugins/
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category audio_interface
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category miscellanea
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category music_service
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category plugins.json
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category system_controller
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category user_interface
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning into folder /data/plugins/
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category audio_interface
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category music_service
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category system_controller
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category system_hardware
Dec 10 09:30:14 volumio volumio[27883]: info: Scanning category user_interface
Dec 10 09:30:14 volumio volumio[27883]: info: Plugin folders cleanup completed
Dec 10 09:30:14 volumio volumio[27883]: info: -------------------------------------------
Dec 10 09:30:14 volumio volumio[27883]: info: ----- Core plugins startup ----
Dec 10 09:30:14 volumio volumio[27883]: info: -------------------------------------------
Dec 10 09:30:14 volumio volumio[27883]: info: Loading plugins from folder /volumio/app/plugins/
Dec 10 09:30:14 volumio volumio[27883]: info: Adding plugin upnp to MyMusic Plugins
Dec 10 09:30:14 volumio volumio[27883]: info: Adding plugin airplay_emulation to MyMusic Plugins
Dec 10 09:30:14 volumio volumio[27883]: info: Adding plugin upnp_browser to MyMusic Plugins
Dec 10 09:30:14 volumio volumio[27883]: info: Loading plugins from folder /data/plugins/
Dec 10 09:30:14 volumio volumio[27883]: info: Loading plugin "system"...
Dec 10 09:30:14 volumio volumio[27883]: info: Loading plugin "appearance"...
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "network"...
Dec 10 09:30:15 volumio volumio[27883]: info: Refreshing Cached IP Addresses
Dec 10 09:30:15 volumio sudo[27920]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 10 09:30:15 volumio sudo[27920]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:15 volumio sudo[27922]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 10 09:30:15 volumio sudo[27920]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:15 volumio sudo[27922]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "services"...
Dec 10 09:30:15 volumio sudo[27922]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "alsa_controller"...
Dec 10 09:30:15 volumio sudo[27930]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 10 09:30:15 volumio sudo[27930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:15 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "wizard"...
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "networkfs"...
Dec 10 09:30:15 volumio volumio[27883]: info: Starting Udev Watcher for removable devices
Dec 10 09:30:15 volumio volumio[27883]: info: Ignoring mount for partition: boot
Dec 10 09:30:15 volumio volumio[27883]: info: Ignoring mount for partition: volumio
Dec 10 09:30:15 volumio volumio[27883]: info: Ignoring mount for partition: volumio_data
Dec 10 09:30:15 volumio volumio[27883]: info: Mounting Device Wikipedia
Dec 10 09:30:15 volumio sudo[27959]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime
Dec 10 09:30:15 volumio sudo[27959]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:15 volumio sudo[27959]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:15 volumio volumio[27883]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 10 09:30:15 volumio volumio[27883]: dmesg(1) may have more information after failed mount system call.
Dec 10 09:30:15 volumio volumio[27883]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime
Dec 10 09:30:15 volumio volumio[27883]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia.
Dec 10 09:30:15 volumio volumio[27883]: dmesg(1) may have more information after failed mount system call.
Dec 10 09:30:15 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "volumio_command_line_client"...
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "upnp"...
Dec 10 09:30:15 volumio volumio[27883]: info: [1765380615768] Starting Upmpd Daemon
Dec 10 09:30:15 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "my_music"...
Dec 10 09:30:15 volumio volumio[27883]: info: Loading plugin "mpd"...
Dec 10 09:30:16 volumio volumio-remote-updater[9752]: [2025-12-10 09:30:16] [connect] Successful connection
Dec 10 09:30:16 volumio volumio[27883]: info: Loading plugin "upnp_browser"...
Dec 10 09:30:16 volumio sudo[27930]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 54.
Dec 10 09:30:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:16 volumio go-librespot[27961]: go-librespot daemon starting...
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=debug msg="app state loaded"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=info msg="zeroconf server listening on port 41945"
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=debug msg="obtained new client token: AABMxBmNEW3GwEUFdwiwUytCRB13UIy39xHCWlxEM4WxMud31aEPObgSG4TjVOx9sMrO4uvzy0w40uHRtEIF7Jz/FM5HyqRAjxITAC/HHhMM128EefVHcJM6hQALPqDxEua06zQ8yic20e2iK6Z5DwHhoOOCbRYPXCj8FzDWu1Sg7UfDj/AIHz3OpLB+mVmUU2x/ErDTTYsItO/qQwl9XkmGLSCGncqdWoYaifu5eUnMw+fyHTtblR3DEg=="
Dec 10 09:30:16 volumio go-librespot[27962]: time="2025-12-10T09:30:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:17 volumio go-librespot[27962]: time="2025-12-10T09:30:17-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:17 volumio go-librespot[27962]: time="2025-12-10T09:30:17-06:00" level=debug msg="completed challenge"
Dec 10 09:30:17 volumio go-librespot[27962]: time="2025-12-10T09:30:17-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:17 volumio volumio[27883]: info: Loading plugin "alarm-clock"...
Dec 10 09:30:17 volumio volumio[27883]: info: Loading plugin "airplay_emulation"...
Dec 10 09:30:17 volumio volumio[27883]: info: Starting Shairport Sync
Dec 10 09:30:17 volumio volumio[27883]: info: Loading plugin "last_100"...
Dec 10 09:30:17 volumio volumio[27883]: info: Loading plugin "webradio"...
Dec 10 09:30:17 volumio volumio[27883]: info: Loading plugin "i2s_dacs"...
Dec 10 09:30:17 volumio volumio[27883]: info: I2S DAC not set, start Auto-detection
Dec 10 09:30:17 volumio volumio[27883]: info: Loading plugin "volumiodiscovery"...
Dec 10 09:30:17 volumio volumio[27883]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:30:17 volumio volumio[27883]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:30:17 volumio volumio[27883]: *** WARNING *** For more information see
Dec 10 09:30:17 volumio volumio[27883]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:30:17 volumio volumio[27883]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:30:17 volumio volumio[27883]: *** WARNING *** For more information see
Dec 10 09:30:17 volumio node[27883]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:30:17 volumio node[27883]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:30:17 volumio node[27883]: *** WARNING *** For more information see
Dec 10 09:30:17 volumio node[27883]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Dec 10 09:30:17 volumio node[27883]: *** WARNING *** Please fix your application to use the native API of Avahi!
Dec 10 09:30:17 volumio node[27883]: *** WARNING *** For more information see
Dec 10 09:30:17 volumio volumio[27883]: info: Applying required configuration parameters for plugin volumiodiscovery
Dec 10 09:30:18 volumio volumio[27883]: info: Discovery: Started advertising with name: Volumio
Dec 10 09:30:18 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
Dec 10 09:30:18 volumio volumio[27883]: info: Loading plugin "bandcamp"...
Dec 10 09:30:19 volumio volumio[27883]: info: Plugin calmradio is not enabled
Dec 10 09:30:19 volumio volumio[27883]: info: Loading plugin "soundcloud"...
Dec 10 09:30:19 volumio volumio[27883]: info: Loading plugin "spop"...
Dec 10 09:30:20 volumio volumio[27883]: info: Loading plugin "squeezelite_mc"...
Dec 10 09:30:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55.
Dec 10 09:30:20 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:20 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:20 volumio go-librespot[27972]: go-librespot daemon starting...
Dec 10 09:30:20 volumio go-librespot[27973]: time="2025-12-10T09:30:20-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:20 volumio go-librespot[27973]: time="2025-12-10T09:30:20-06:00" level=debug msg="app state loaded"
Dec 10 09:30:20 volumio go-librespot[27973]: time="2025-12-10T09:30:20-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:20 volumio go-librespot[27973]: time="2025-12-10T09:30:20-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=info msg="zeroconf server listening on port 42017"
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=debug msg="obtained new client token: AAAfL5sheIZ9RcCnYQamR9nru5teIzUEVOjnxDxMM3cM8KqzQY2bY9rbSTreBk0l9HQHAYC2XLnIPQuAklhiJGSXsctiVs7w9K+xD1dQ998d51swBFA4vMxWJVpIaCjtn8u0BmYsY9Nuu2ROsyTRZKqkfqaCCUlfPjSqhwpPWkH5/mJuwbysRXyCwTXBRkaUse8GUuBSjH9khkrAILRO6jVi/fRVwh8HK8J00cF5NavJUVKD2QIq+yk="
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=debug msg="completed challenge"
Dec 10 09:30:21 volumio volumio[27883]: info: Loading plugin "youtube2"...
Dec 10 09:30:21 volumio go-librespot[27973]: time="2025-12-10T09:30:21-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:22 volumio volumio[27883]: info: Loading plugin "ytcr"...
Dec 10 09:30:23 volumio volumio[27883]: info: Loading plugin "ytmusic"...
Dec 10 09:30:23 volumio volumio[27883]: info: Plugin now_playing is not enabled
Dec 10 09:30:23 volumio volumio[27883]: info: Loading plugin "outputs"...
Dec 10 09:30:23 volumio volumio[27883]: info: Loading plugin "albumart"...
Dec 10 09:30:23 volumio volumio[27883]: info: Plugin example_plugin is not enabled
Dec 10 09:30:23 volumio volumio[27883]: info: Loading plugin "inputs"...
Dec 10 09:30:23 volumio volumio[27883]: info: Loading plugin "updater_comm"...
Dec 10 09:30:23 volumio volumio[27883]: info: Plugin mpdemulation is not enabled
Dec 10 09:30:23 volumio volumio[27883]: info: Loading plugin "rest_api"...
Dec 10 09:30:23 volumio volumio[27883]: info: Loading plugin "websocket"...
Dec 10 09:30:24 volumio volumio[27883]: info: Starting Socket.io Server version 1.7.4
Dec 10 09:30:24 volumio volumio[27883]: info: Plugin fusiondsp is not enabled
Dec 10 09:30:24 volumio volumio[27883]: info: Plugin mpdoutput is not enabled
Dec 10 09:30:24 volumio volumio[27883]: info: Plugin RoonBridge is not enabled
Dec 10 09:30:24 volumio volumio[27883]: info: Loading plugin "podcast"...
Dec 10 09:30:24 volumio volumio[27883]: info: ControllerPodcast::constructor
Dec 10 09:30:24 volumio volumio[27883]: info: Loading plugin "volusonic"...
Dec 10 09:30:24 volumio volumio[27980]: Forking 3 albumart workers
Dec 10 09:30:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56.
Dec 10 09:30:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:24 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:24 volumio go-librespot[28003]: go-librespot daemon starting...
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=debug msg="app state loaded"
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:24 volumio go-librespot[28021]: time="2025-12-10T09:30:24-06:00" level=info msg="zeroconf server listening on port 40017"
Dec 10 09:30:25 volumio go-librespot[28021]: time="2025-12-10T09:30:25-06:00" level=debug msg="obtained new client token: AADxfTwzHHb8eZ6h5mpaS+SCbVLOZfCNAYXaUq7TcNm57agwetLS/7VNfodFGwIRmuRrRS+9Y3yG10h7boynJa1gMHxn2MVNyQDeYPXs7qSXhnYjFQpX96lLkMmul1inNTkYi0hc2v2KlVAhdwb9K5So4G64zID+FYv82bZNz2rTGLnt4htniO4t2vJ7CZRJCoI3emsRvgHZL9iJhoh8E6dhZUVKWR8jHOttS6cTAT4BX5xLHIkPCEiEQw=="
Dec 10 09:30:25 volumio go-librespot[28021]: time="2025-12-10T09:30:25-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:25 volumio go-librespot[28021]: time="2025-12-10T09:30:25-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:25 volumio go-librespot[28021]: time="2025-12-10T09:30:25-06:00" level=debug msg="completed challenge"
Dec 10 09:30:25 volumio go-librespot[28021]: time="2025-12-10T09:30:25-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:25 volumio volumio[27883]: info: Applying required configuration parameters for plugin volusonic
Dec 10 09:30:25 volumio volumio[27883]: info: Loading plugin "backup_restore"...
Dec 10 09:30:26 volumio volumio[27990]: Starting albumart workers
Dec 10 09:30:26 volumio volumio[27883]: info: Applying required configuration parameters for plugin backup_restore
Dec 10 09:30:26 volumio volumio[27883]: info: Plugin rpi_eeprom_config is not enabled
Dec 10 09:30:26 volumio volumio[27883]: info: Plugin rpi_eeprom_updater is not enabled
Dec 10 09:30:26 volumio volumio[27883]: info: Loading plugin "scheduledrestart"...
Dec 10 09:30:26 volumio volumio[27992]: Starting albumart workers
Dec 10 09:30:26 volumio volumio[27991]: Starting albumart workers
Dec 10 09:30:26 volumio volumio[27883]: info: Applying required configuration parameters for plugin scheduledrestart
Dec 10 09:30:26 volumio volumio[27883]: info: Plugin Bluetoothremote is not enabled
Dec 10 09:30:26 volumio volumio[27883]: info: Plugin music_services_shield is not enabled
Dec 10 09:30:26 volumio volumio[27883]: info: Loading plugin "Systeminfo"...
Dec 10 09:30:26 volumio volumio[27883]: info: Plugin peppymeterbasic is not enabled
Dec 10 09:30:26 volumio volumio[27883]: info: Loading plugin "peppyspectrum"...
Dec 10 09:30:27 volumio volumio[27883]: info: Loading i18n strings for locale en
Dec 10 09:30:27 volumio volumio[27883]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 10 09:30:27 volumio volumio[27883]: Updating browse sources language
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::initPlayerControls
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: Express server listening on port 3000
Dec 10 09:30:27 volumio volumio[27883]: [Metrics] WebUI: 14s 429.94ms
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::resetVolumioState
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::getcurrentVolume
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::volumioRetrievevolume
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:27 volumio sudo[28069]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 10 09:30:27 volumio sudo[28069]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:27 volumio sudo[28069]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:27 volumio sudo[28071]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 10 09:30:27 volumio sudo[28071]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:27 volumio sudo[28071]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:27 volumio volumio[27883]: info: Volumio Network Manager: Network status updated: 1
Dec 10 09:30:27 volumio volumio[27883]: info: VolumeController:: Volume=86 Mute =false
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::pushState
Dec 10 09:30:27 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::volumioPushState
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::updateTrackBlock
Dec 10 09:30:27 volumio volumio[27883]: info: CorePlayQueue::getTrackBlock
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::volumioRetrievevolume
Dec 10 09:30:27 volumio volumio[27883]: info: Reloading queue from file
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::setRepeat null single undefined
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::pushState
Dec 10 09:30:27 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::volumioPushState
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::setRandom null
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::pushState
Dec 10 09:30:27 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::volumioPushState
Dec 10 09:30:27 volumio volumio[27883]: info: Setting Device type: Raspberry PI
Dec 10 09:30:27 volumio volumio[27883]: info: VolumeController:: Volume=86 Mute =false
Dec 10 09:30:27 volumio volumio[27883]: info: CoreStateMachine::pushState
Dec 10 09:30:27 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::volumioPushState
Dec 10 09:30:27 volumio volumio[27883]: info: Completed loading Core Plugins
Dec 10 09:30:27 volumio sudo[28084]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 10 09:30:27 volumio sudo[28084]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:27 volumio volumio[27883]: info: Preparing to generate the ALSA configuration file
Dec 10 09:30:27 volumio volumio[27883]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 10 09:30:27 volumio volumio[27883]: info: Reading ALSA contributions from plugins.
Dec 10 09:30:27 volumio volumio[27883]: info: Asound.conf file unchanged, so no further update is needed
Dec 10 09:30:27 volumio volumio[27883]: info: Output device has changed, restarting MPD
Dec 10 09:30:27 volumio sudo[28084]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:27 volumio volumio[27883]: info: Output device has changed, restarting Shairport Sync
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:27 volumio sudo[28087]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 10 09:30:27 volumio sudo[28087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:27 volumio sudo[28087]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:27 volumio sudo[28089]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 10 09:30:27 volumio sudo[28089]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:27 volumio volumio[27883]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:30:27 volumio volumio[27883]: info: ___________ START PLUGINS ___________
Dec 10 09:30:27 volumio volumio[27883]: info: ControllerMpd::onStart: Initializing MPD
Dec 10 09:30:27 volumio volumio[27883]: info: Creating MPD Configuration file
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:27 volumio volumio[27883]: info: [1765380627930] CoreMusicLibrary::Adding element Media Servers
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:27 volumio systemd[1]: Stopping mpd.service - Music Player Daemon...
Dec 10 09:30:27 volumio sudo[28097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 10 09:30:27 volumio sudo[28097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:27 volumio sudo[28097]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:27 volumio sudo[28099]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 10 09:30:27 volumio sudo[28099]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:27 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:28 volumio volumio[27883]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:28 volumio volumio[27883]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628055] CoreMusicLibrary::Adding element Last_100
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 10 09:30:28 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 10 09:30:28 volumio systemd[1]: mpd.service: Consumed 4.521s CPU time.
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628064] CoreMusicLibrary::Adding element Webradio
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 10 09:30:28 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 10 09:30:28 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:30:28 volumio volumio[27883]: info: Initializing BBC Radios
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628137] CoreMusicLibrary::Adding element Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628148] CoreMusicLibrary::Adding element SoundCloud
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:28 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 10 09:30:28 volumio volumio[27883]: info: Creating Spotify config file
Dec 10 09:30:28 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:28 volumio sudo[28124]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 10 09:30:28 volumio sudo[28124]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 10 09:30:28 volumio sudo[28124]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:28 volumio volumio[27883]: info: [squeezelite_mc] Starting proxy server...
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628504] CoreMusicLibrary::Adding element YouTube2
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube2
Dec 10 09:30:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57.
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628524] CoreMusicLibrary::Adding element YouTube Music
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube2
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube Music
Dec 10 09:30:28 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:28 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628540] CoreMusicLibrary::Adding element Podcast
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube2
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube Music
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Podcast
Dec 10 09:30:28 volumio go-librespot[28127]: go-librespot daemon starting...
Dec 10 09:30:28 volumio go-librespot[28128]: time="2025-12-10T09:30:28-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:28 volumio volumio[27883]: info: Loading i18n strings for locale en
Dec 10 09:30:28 volumio volumio[27883]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored.
Dec 10 09:30:28 volumio volumio[27883]: Updating browse sources language
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube2
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube Music
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Podcast
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube2
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube Music
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Podcast
Dec 10 09:30:28 volumio volumio-remote-updater[9752]: [2025-12-10 09:30:28] [connect] Successful connection
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:28 volumio volumio[27883]: info: [1765380628608] CoreMusicLibrary::Adding element Volusonic
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube2
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source YouTube Music
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Podcast
Dec 10 09:30:28 volumio volumio[27883]: Cannot find translation for source Volusonic
Dec 10 09:30:28 volumio volumio[27883]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Dec 10 09:30:28 volumio volumio[27883]: info: Volumio Calling Home
Dec 10 09:30:28 volumio volumio[27883]: info: [squeezelite_mc] Proxy server started on port 32971
Dec 10 09:30:28 volumio volumio[27883]: info: Preparing to generate the ALSA configuration file
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioRetrievevolume
Dec 10 09:30:28 volumio go-librespot[28128]: time="2025-12-10T09:30:28-06:00" level=info msg="zeroconf server listening on port 38407"
Dec 10 09:30:28 volumio volumio[27883]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954
Dec 10 09:30:28 volumio volumio[27883]: info: Discovery: Found device Volumio
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioGetState
Dec 10 09:30:28 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:28 volumio volumio[27883]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954
Dec 10 09:30:28 volumio volumio[27883]: info: Discovery: Found device Volumio
Dec 10 09:30:28 volumio volumio[27883]: info: CoreCommandRouter::volumioGetState
Dec 10 09:30:28 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:28 volumio volumio[27883]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf
Dec 10 09:30:28 volumio volumio[27883]: info: Reading ALSA contributions from plugins.
Dec 10 09:30:28 volumio volumio[27883]: info: MPD Permissions set
Dec 10 09:30:28 volumio volumio[27883]: info: MPD Permissions set
Dec 10 09:30:28 volumio volumio[27883]: info: Upmpdcli Daemon Started
Dec 10 09:30:28 volumio volumio-remote-updater[9752]: [2025-12-10 09:30:28] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765380628 101
Dec 10 09:30:28 volumio volumio[27883]: 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 10 09:30:29 volumio volumio[27883]: info: Spotify config file written
Dec 10 09:30:29 volumio sudo[28141]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Dec 10 09:30:29 volumio sudo[28141]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:29 volumio systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon...
Dec 10 09:30:29 volumio systemd[1]: go-librespot-daemon.service: Deactivated successfully.
Dec 10 09:30:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:29 volumio volumio[27883]: 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 10 09:30:29 volumio volumio[27883]: info: VolumeController:: Volume=86 Mute =false
Dec 10 09:30:29 volumio volumio[27883]: info: CoreStateMachine::pushState
Dec 10 09:30:29 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::volumioPushState
Dec 10 09:30:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:29 volumio volumio[27883]: info: [squeezelite_mc] Server discovery started
Dec 10 09:30:29 volumio volumio[27883]: info: [squeezelite_mc] Player finder started
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio go-librespot[28143]: go-librespot daemon starting...
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:30:29 volumio sudo[28141]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:29 volumio volumio[27883]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="app state loaded"
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: No need to fix Spotify hosts
Dec 10 09:30:29 volumio volumio[27883]: 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 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:29 volumio volumio[27883]: info: Volumio called home
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=info msg="zeroconf server listening on port 45363"
Dec 10 09:30:29 volumio volumio[27883]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}
Dec 10 09:30:29 volumio volumio[27883]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"]
Dec 10 09:30:29 volumio volumio[27883]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"}
Dec 10 09:30:29 volumio volumio[27883]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 10 09:30:29 volumio volumio[27883]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 10 09:30:29 volumio volumio[27883]: SPOTIFY: BQCAM6tsLHnrg_whe1Hg1ty1Qk7-Fc2bdAFjNtieZJ6-GdCateVPwS2mApVhZXp2ADuYKsK_zJS-wFgyOYmFsu_2fZ843AkxvS0tp1xFBvm8FhcbRLJN-bQGqI7p-LoVKsph8LfvVF3qHjT6mlENNrrMLKsFDT-IZI-1J4Suc0s1H2eDbFH5suglS23-TINNePrjFTnBbpEAWedKWlciREJ9lu_hcJ7XcCbnKbI
Dec 10 09:30:29 volumio volumio[27883]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------
Dec 10 09:30:29 volumio volumio[27883]: info: New Spotify access token = BQCAM6tsLHnrg_whe1Hg1ty1Qk7-Fc2bdAFjNtieZJ6-GdCateVPwS2mApVhZXp2ADuYKsK_zJS-wFgyOYmFsu_2fZ843AkxvS0tp1xFBvm8FhcbRLJN-bQGqI7p-LoVKsph8LfvVF3qHjT6mlENNrrMLKsFDT-IZI-1J4Suc0s1H2eDbFH5suglS23-TINNePrjFTnBbpEAWedKWlciREJ9lu_hcJ7XcCbnKbI
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="obtained new client token: AACxZs3+x0y1Pq9T6HaB9e5P9qEcyXumlhL0iqsuUQ+35iiAXT775n4xIn9+XY7kzutQ5Cd5ifP8OPK+53HyXAlDXqCmp/LzNpKhTj2uYdV97op687oOMGUYldHJ+7M1u7xQlCPoxeZx5FYnsMG56ciMdUb0UgxLe7/tdJSjpSw8lV6JP9r4/kM83lkza6p0bZYaY0HycXUIyoaOTPrSthj8Lsv90fucZCcFMvnXn04AcpiYTs+pkDy9kg=="
Dec 10 09:30:29 volumio volumio[27883]: info: Spotify credentials grant success - running version from March 24, 2019
Dec 10 09:30:29 volumio volumio[27883]: info: Starting Shairport Sync
Dec 10 09:30:29 volumio volumio[27883]: info: Starting Shairport Sync
Dec 10 09:30:29 volumio volumio[27883]: info: Starting Shairport Sync
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:29 volumio sudo[28169]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:30:29 volumio sudo[28169]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:29 volumio sudo[28171]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:30:29 volumio sudo[28174]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:30:29 volumio sudo[28171]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:29 volumio sudo[28174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:29 volumio volumio[27883]: info: Asound.conf file unchanged, so no further update is needed
Dec 10 09:30:29 volumio volumio[27883]: info: Output device has changed, restarting MPD
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=debug msg="completed challenge"
Dec 10 09:30:29 volumio volumio[27883]: info: Output device has changed, restarting Shairport Sync
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:29 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 10 09:30:29 volumio sudo[28166]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf
Dec 10 09:30:29 volumio sudo[28166]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:29 volumio go-librespot[28144]: time="2025-12-10T09:30:29-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 10 09:30:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:30:29 volumio systemd[1]: shairport-sync.service: Consumed 1.788s CPU time.
Dec 10 09:30:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:29 volumio sudo[28180]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Dec 10 09:30:29 volumio sudo[28180]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:29 volumio sudo[28166]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:29 volumio sudo[28180]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:29 volumio sudo[28181]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Dec 10 09:30:29 volumio sudo[28181]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:29 volumio volumio[27883]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Dec 10 09:30:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:30:29 volumio sudo[28171]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:29 volumio sudo[28169]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:30 volumio volumio[27883]: info: MPD Permissions set
Dec 10 09:30:30 volumio volumio[27883]: info: [squeezelite_mc] Executing alsactl -L -R nrestore
Dec 10 09:30:30 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 10 09:30:30 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 10 09:30:30 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:30:30 volumio systemd[1]: mpd.service: Deactivated successfully.
Dec 10 09:30:30 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Dec 10 09:30:30 volumio systemd[1]: mpd.service: Consumed 1.607s CPU time.
Dec 10 09:30:30 volumio systemd[1]: mpd.socket: Deactivated successfully.
Dec 10 09:30:30 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Dec 10 09:30:30 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Dec 10 09:30:30 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Dec 10 09:30:30 volumio volumio[27883]: info: Shairport-Sync Started
Dec 10 09:30:30 volumio sudo[28195]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore
Dec 10 09:30:30 volumio volumio[27883]: Error adding Membership: Error: addMembership EINVAL
Dec 10 09:30:30 volumio volumio[27883]: info: Shairport-Sync Started
Dec 10 09:30:30 volumio sudo[28195]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:30 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Dec 10 09:30:30 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:30:30 volumio sudo[28174]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:30 volumio sudo[28195]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:30 volumio volumio[27883]: info: Shairport-Sync Started
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::volumioGetState
Dec 10 09:30:30 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:30 volumio volumio[27883]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 10 09:30:30 volumio volumio[27883]: info: Starting Shairport Sync
Dec 10 09:30:30 volumio volumio[27883]: SPOTIFY: User informations: {"display_name":"Clint Smith","external_urls":{"spotify":"https://open.spotify.com/user/clintsmith1"},"followers":{"href":null,"total":7},"href":"https://api.spotify.com/v1/users/clintsmith1","id":"clintsmith1","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee856520409d25d9cc210472a0fd","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b826520409d25d9cc210472a0fd","width":64}],"type":"user","uri":"spotify:user:clintsmith1"}
Dec 10 09:30:30 volumio volumio[27883]: info: Spotify Successfully logged in
Dec 10 09:30:30 volumio sudo[28197]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Dec 10 09:30:30 volumio volumio[27883]: info: [1765380630372] CoreMusicLibrary::Adding element Spotify
Dec 10 09:30:30 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 10 09:30:30 volumio volumio[27883]: Cannot find translation for source Bandcamp Discover
Dec 10 09:30:30 volumio volumio[27883]: Cannot find translation for source SoundCloud
Dec 10 09:30:30 volumio volumio[27883]: Cannot find translation for source YouTube2
Dec 10 09:30:30 volumio volumio[27883]: Cannot find translation for source YouTube Music
Dec 10 09:30:30 volumio volumio[27883]: Cannot find translation for source Podcast
Dec 10 09:30:30 volumio volumio[27883]: Cannot find translation for source Volusonic
Dec 10 09:30:30 volumio volumio[27883]: Cannot find translation for source Spotify
Dec 10 09:30:30 volumio sudo[28197]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Dec 10 09:30:30 volumio sudo[28224]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Dec 10 09:30:30 volumio sudo[28224]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:30 volumio sudo[28197]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:30 volumio sudo[28222]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service
Dec 10 09:30:30 volumio sudo[28222]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:30 volumio sudo[28222]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:30 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Dec 10 09:30:30 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Dec 10 09:30:30 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:30:30 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Dec 10 09:30:30 volumio sudo[28224]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:30 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true
Dec 10 09:30:30 volumio volumio[27883]: info: Shairport-Sync Started
Dec 10 09:30:30 volumio sudo[28231]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload
Dec 10 09:30:30 volumio sudo[28231]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:30 volumio systemd[1]: Reloading.
Dec 10 09:30:30 volumio volumio[27883]: info: [squeezelite_mc] Notification listener started
Dec 10 09:30:30 volumio volumio[27883]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 10 09:30:31 volumio volumio[27883]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 10 09:30:31 volumio volumio[27883]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 10 09:30:31 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:31 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:31 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Dec 10 09:30:31 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Dec 10 09:30:32 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:32 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:32 volumio volumio[27883]: info: go-librespot daemon successfully initialized
Dec 10 09:30:32 volumio sudo[28231]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:32 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:32 volumio sudo[28265]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:32 volumio sudo[28265]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:32 volumio volumio[27883]: info: CoreCommandRouter::volumioGetState
Dec 10 09:30:32 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:32 volumio sudo[28265]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:32 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true
Dec 10 09:30:32 volumio sudo[28268]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite
Dec 10 09:30:32 volumio sudo[28268]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1.
Dec 10 09:30:32 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:32 volumio go-librespot[28270]: go-librespot daemon starting...
Dec 10 09:30:32 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:32 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 10 09:30:32 volumio go-librespot[28271]: time="2025-12-10T09:30:32-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:32 volumio go-librespot[28271]: time="2025-12-10T09:30:32-06:00" level=debug msg="app state loaded"
Dec 10 09:30:32 volumio go-librespot[28271]: time="2025-12-10T09:30:32-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:32 volumio go-librespot[28271]: time="2025-12-10T09:30:32-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:33 volumio volumio[27883]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect'
Dec 10 09:30:33 volumio volumio[27883]: info: CoreCommandRouter::volumioGetState
Dec 10 09:30:33 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:33 volumio systemd[1]: squeezelite.service: Deactivated successfully.
Dec 10 09:30:33 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=info msg="zeroconf server listening on port 38149"
Dec 10 09:30:33 volumio sudo[28268]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=debug msg="obtained new client token: AABMNplYhqX7zw3Wg182g8WWhFXysFjMZjhkP47eBZwrw0sSxCak3XX4mL9PzA36KbAVUV0OLnaULD1O/Hxz56YCIn80vEHaz6DFYNAkmXikquOE/i3302chWxubKPx6Re/EEj1sPUZRv8q6+e3dTqqQxkmvgUxkpmwNwz7biqM1eaZJhT6R68F1mCNJo1uke7oyw2q+SOe44dqQ3L9qsl1OUlRmNow7HvdDZasz4nJecLH0uApbs/HfLA=="
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=debug msg="completed challenge"
Dec 10 09:30:33 volumio go-librespot[28271]: time="2025-12-10T09:30:33-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:33 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:33 volumio sudo[28280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:33 volumio sudo[28280]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:33 volumio sudo[28280]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:33 volumio volumio[27883]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log
Dec 10 09:30:33 volumio sudo[28284]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log
Dec 10 09:30:33 volumio sudo[28284]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:33 volumio sudo[28284]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:33 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true
Dec 10 09:30:33 volumio sudo[28287]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite
Dec 10 09:30:33 volumio sudo[28287]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:34 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator...
Dec 10 09:30:34 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator.
Dec 10 09:30:34 volumio sudo[28287]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:34 volumio mpd[28227]: 2025-12-10T09:30:34 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Dec 10 09:30:34 volumio volumio[27883]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect'
Dec 10 09:30:34 volumio volumio[27883]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180)
Dec 10 09:30:34 volumio volumio[27883]: info: [squeezelite_mc] Players connected to BigBoss (192.168.1.180): [{"id":"00:04:20:27:50:e8","uuid":"01ef6d9b3e5a11e37681969e3bc3ac56","ip":"192.168.1.148","name":"Squeezebox Radio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}},{"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}]
Dec 10 09:30:34 volumio volumio[27883]: info: [squeezelite_mc] Player found: {"id":"b8:27:eb:bb:d5:b0","uuid":null,"ip":"192.168.1.221","name":"volumio","server":{"ip":"192.168.1.180","name":"BigBoss","ver":"7.999.999","uuid":"d9ef138b-f3d6-4b57-9529-029da004b8f2","jsonPort":"9006","cliPort":"9090"}}
Dec 10 09:30:34 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Dec 10 09:30:34 volumio sudo[28089]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:34 volumio sudo[28181]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:34 volumio sudo[28099]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:34 volumio volumio[27883]: error: MPD error: The expression evaluated to a falsy value:
Dec 10 09:30:34 volumio volumio[27883]: assert.ok(self.idling)
Dec 10 09:30:34 volumio volumio[27883]: error: The expression evaluated to a falsy value:
Dec 10 09:30:34 volumio volumio[27883]: assert.ok(self.idling)
Dec 10 09:30:34 volumio volumio[27883]: error: MPD error: The expression evaluated to a falsy value:
Dec 10 09:30:34 volumio volumio[27883]: assert.ok(self.idling)
Dec 10 09:30:34 volumio volumio[27883]: error: The expression evaluated to a falsy value:
Dec 10 09:30:34 volumio volumio[27883]: assert.ok(self.idling)
Dec 10 09:30:34 volumio volumio[27883]: error: updateQueue error: null
Dec 10 09:30:34 volumio volumio[27883]: info: MPD running with PID28227
Dec 10 09:30:34 volumio volumio[27883]: ,establishing connection
Dec 10 09:30:34 volumio volumio[27883]: error: updateQueue error: null
Dec 10 09:30:34 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:34 volumio sudo[28298]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:34 volumio sudo[28298]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:34 volumio sudo[28298]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:35 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:35 volumio sudo[28301]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:35 volumio sudo[28301]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:35 volumio sudo[28301]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:35 volumio volumio[27883]: info: CoreCommandRouter::volumioGetState
Dec 10 09:30:35 volumio volumio[27883]: info: CorePlayQueue::getTrack 0
Dec 10 09:30:35 volumio volumio[27883]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:35 volumio volumio[27883]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:30:35 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:35 volumio sudo[28318]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:35 volumio sudo[28318]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:35 volumio sudo[28318]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:36 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:36 volumio sudo[28321]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:36 volumio sudo[28321]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:36 volumio sudo[28321]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2.
Dec 10 09:30:36 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:36 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:36 volumio go-librespot[28323]: go-librespot daemon starting...
Dec 10 09:30:36 volumio go-librespot[28324]: time="2025-12-10T09:30:36-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:36 volumio go-librespot[28324]: time="2025-12-10T09:30:36-06:00" level=debug msg="app state loaded"
Dec 10 09:30:36 volumio go-librespot[28324]: time="2025-12-10T09:30:36-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:36 volumio go-librespot[28324]: time="2025-12-10T09:30:36-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:36 volumio volumio[27883]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true
Dec 10 09:30:36 volumio go-librespot[28324]: time="2025-12-10T09:30:36-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:36 volumio go-librespot[28324]: time="2025-12-10T09:30:36-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:36 volumio go-librespot[28324]: time="2025-12-10T09:30:36-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:37 volumio go-librespot[28324]: time="2025-12-10T09:30:37-06:00" level=info msg="zeroconf server listening on port 43709"
Dec 10 09:30:37 volumio sudo[28332]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite
Dec 10 09:30:37 volumio sudo[28332]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:37 volumio sudo[28332]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:37 volumio volumio[27883]: info: Completed starting Core Plugins
Dec 10 09:30:37 volumio volumio[27883]: info: -------------------------------------------
Dec 10 09:30:37 volumio volumio[27883]: info: ----- MyVolumio plugins startup ----
Dec 10 09:30:37 volumio volumio[27883]: info: -------------------------------------------
Dec 10 09:30:37 volumio volumio[27883]: info: [MyVolumio PluginManager] Fetching plans data....
Dec 10 09:30:37 volumio go-librespot[28324]: time="2025-12-10T09:30:37-06:00" level=debug msg="obtained new client token: AADZX1Y6pDXJJ4Kij9KmLTpWxr6XyB1TuXIqon8/ozETRp7Xen4nPglGCquoLjaI6PBpieRh6kvMwa7REm+xVTncksbou/3/At7Zh9gUTYfGFh3Uo9WgCDjxoGH1P2ZqNlN77v58ftyfeT/pINnSj42ZLS6Gdho7+cMrisHtGto8fEqVS++ONObjbDrJbeT0oJZiK02ygjr/Fx/bNzRHH3roLsxYkuSSXyCO4y0R2yL8x6rwjhvcgxg="
Dec 10 09:30:37 volumio go-librespot[28324]: time="2025-12-10T09:30:37-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:37 volumio go-librespot[28324]: time="2025-12-10T09:30:37-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:37 volumio go-librespot[28324]: time="2025-12-10T09:30:37-06:00" level=debug msg="completed challenge"
Dec 10 09:30:37 volumio go-librespot[28324]: time="2025-12-10T09:30:37-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:37 volumio sudo[28336]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 10 09:30:37 volumio sudo[28336]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:37 volumio sudo[28338]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 10 09:30:37 volumio sudo[28338]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:37 volumio sudo[28340]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service
Dec 10 09:30:37 volumio sudo[28340]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:37 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service...
Dec 10 09:30:37 volumio systemd[1]: mpd_monitor.service: Deactivated successfully.
Dec 10 09:30:37 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service.
Dec 10 09:30:37 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service.
Dec 10 09:30:37 volumio sudo[28336]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:37 volumio sudo[28340]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:37 volumio mpd_monitor.sh[28344]: MPD Monitor Service: Starting MPD Monitor Service
Dec 10 09:30:37 volumio sudo[28338]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:37 volumio volumio[27883]: info: Successfully started MPD Monitor
Dec 10 09:30:37 volumio volumio[27883]: info: Successfully started MPD Monitor
Dec 10 09:30:37 volumio volumio[27883]: info: Successfully started MPD Monitor
Dec 10 09:30:38 volumio volumio[27883]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:38 volumio volumio[27883]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:30:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3.
Dec 10 09:30:40 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:40 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:40 volumio go-librespot[28349]: go-librespot daemon starting...
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=debug msg="app state loaded"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=info msg="zeroconf server listening on port 34311"
Dec 10 09:30:40 volumio go-librespot[28350]: time="2025-12-10T09:30:40-06:00" level=debug msg="obtained new client token: AABpENLlII1ka5jXOXeRRBVXU5LcciJ/35KlaEkM+ua5aamiWExmydVfP4SfghSuPSrRlAmpNiJ7Sp3IgOeEJnlYZePXj9TUpGeHJjD7xSFVeNKbLDVm1u0eKuGZJ96mrbmc7yc1/ZRWMbFJ1/xbKxLcUjxKwOL4Yr9pVs1vO+BnRER+xq9fgFNKlIlSw54CHawL9XXVj3cHbwlWTYJXCRQBdQds3J/INgCwaQp8Pgp1AVsyDV2CQGA8PQ=="
Dec 10 09:30:41 volumio go-librespot[28350]: time="2025-12-10T09:30:41-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:41 volumio go-librespot[28350]: time="2025-12-10T09:30:41-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:41 volumio go-librespot[28350]: time="2025-12-10T09:30:41-06:00" level=debug msg="completed challenge"
Dec 10 09:30:41 volumio go-librespot[28350]: time="2025-12-10T09:30:41-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:42 volumio volumio[27883]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:42 volumio volumio[27883]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:30:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4.
Dec 10 09:30:44 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:44 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:44 volumio go-librespot[28357]: go-librespot daemon starting...
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="app state loaded"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=info msg="zeroconf server listening on port 37865"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="obtained new client token: AABl8XC595F2IevcBxtD6P0tWWJRrzygNmtd6iOAWWQudKfHUb1X76JfPB0zgPt70Ywk+r6V9G1mMTkcb0h9pchQt2ZHZZGnwSjUsmU+ne9GAayV7zae+W3nL9qc2RpWlVRyu/i6H6sRbDJ+etg6Jn/YZpbeqL9BrFOHKJt9tCt7ZtdZmspBuO86mx5hjd04VDzv90XgWbysL1dKRMHbtqgRyMec73PFrRos2p4E/hqnz4p0fHR4j19rAw=="
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=debug msg="completed challenge"
Dec 10 09:30:44 volumio go-librespot[28358]: time="2025-12-10T09:30:44-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:45 volumio volumio[27883]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:45 volumio volumio[27883]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Dec 10 09:30:45 volumio volumio[27883]: info: Adding plugin bluetooth to MyMusic Plugins
Dec 10 09:30:45 volumio volumio[27883]: info: Adding plugin multiroom to MyMusic Plugins
Dec 10 09:30:45 volumio volumio[27883]: info: Adding plugin metavolumio to MyMusic Plugins
Dec 10 09:30:45 volumio volumio[27883]: info: Adding plugin cd_controller to MyMusic Plugins
Dec 10 09:30:45 volumio volumio[27883]: info: Adding plugin qobuzconnect to MyMusic Plugins
Dec 10 09:30:45 volumio volumio[27883]: info: Adding plugin smart_inputs to MyMusic Plugins
Dec 10 09:30:45 volumio volumio[27883]: info: Adding plugin tidalconnect to MyMusic Plugins
Dec 10 09:30:45 volumio volumio[27883]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Dec 10 09:30:46 volumio volumio[27883]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Dec 10 09:30:46 volumio volumio[27883]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Dec 10 09:30:46 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:46 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:46 volumio volumio[27883]: info: Starting MyVolumio Remote Streaming Endpoints
Dec 10 09:30:46 volumio volumio[27883]: info: MyVolumio login type: Token
Dec 10 09:30:46 volumio volumio[27883]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Dec 10 09:30:46 volumio volumio[27883]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Dec 10 09:30:47 volumio volumio[27883]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Dec 10 09:30:47 volumio volumio[27883]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Dec 10 09:30:47 volumio volumio[27883]: info: Streaming services startup
Dec 10 09:30:47 volumio volumio[27883]: info: Starting Streaming Daemon
Dec 10 09:30:47 volumio sudo[28380]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 10 09:30:47 volumio sudo[28380]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:47 volumio volumio[27883]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Dec 10 09:30:47 volumio sudo[28380]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:47 volumio volumio[27883]: error: Cannot start Volumio Streaming Daemon
Dec 10 09:30:47 volumio volumio[27883]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 10 09:30:47 volumio volumio[27883]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 10 09:30:47 volumio volumio[27883]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Dec 10 09:30:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5.
Dec 10 09:30:47 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:48 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:48 volumio go-librespot[28386]: go-librespot daemon starting...
Dec 10 09:30:48 volumio volumio[27883]: info: MyVolumio token set successfully
Dec 10 09:30:48 volumio volumio[27883]: info: MYVOLUMIO: Adding device
Dec 10 09:30:48 volumio volumio[27883]: info: MYVOLUMIO: Evaluating Server
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="app state loaded"
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:48 volumio volumio[27883]: info: Initializing connection to go-librespot Websocket
Dec 10 09:30:48 volumio volumio[27883]: info: MyVolumio status changed
Dec 10 09:30:48 volumio volumio[27883]: info: Streaming services startup
Dec 10 09:30:48 volumio volumio[27883]: info: Starting Streaming Daemon
Dec 10 09:30:48 volumio volumio[27883]: info: Removing browser output: myVolumio user plan is not superstar
Dec 10 09:30:48 volumio volumio[27883]: info: Removing audio output:
Dec 10 09:30:48 volumio volumio[27883]: info: Stoppping Tunnel 1
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:48 volumio sudo[28415]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Dec 10 09:30:48 volumio sudo[28415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=info msg="zeroconf server listening on port 38511"
Dec 10 09:30:48 volumio sudo[28417]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Dec 10 09:30:48 volumio sudo[28417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="new websocket client"
Dec 10 09:30:48 volumio volumio[27883]: info: Connection to go-librespot Websocket established
Dec 10 09:30:48 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:48 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:48 volumio sudo[28415]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:48 volumio volumio[27883]: error: Cannot start Volumio Streaming Daemon
Dec 10 09:30:48 volumio volumio[27883]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Dec 10 09:30:48 volumio volumio[27883]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Dec 10 09:30:48 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:48 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:48 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:48 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Dec 10 09:30:48 volumio sudo[28417]: pam_unix(sudo:session): session closed for user root
Dec 10 09:30:48 volumio volumio[27883]: info: Remote SSH Stopped
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="obtained new client token: AADkpXVFwkXBhcG3dtpV6K4IxL7mYIGAACJMTQWm9qAs160VyaRiaDHWGZCZp2ShK49/hHqZWTKdtqE5Oc6cDEnVrFsE5fSZbnKkF8Er7tamVFehWKscqtsYCBAM5AK87Hm52j6pGCp7YKEnm8hai4amc3fXcweG4j46ZvhJ4GmLTTQ0VWPI8tCaSB+BeJl4MMbn9YAaYLQTG4mFwtg+4+jg8A5H7Eo5tQrJiUfTM7vNQ4HQEwwyt3sOsQ=="
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:48 volumio volumio[27883]: info: Setting Geolocation for MyVolumio to us1
Dec 10 09:30:48 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:48 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:48 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=debug msg="completed challenge"
Dec 10 09:30:48 volumio go-librespot[28389]: time="2025-12-10T09:30:48-06:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials "
Dec 10 09:30:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Dec 10 09:30:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Dec 10 09:30:48 volumio volumio[27883]: info: Connection to go-librespot Websocket closed
Dec 10 09:30:49 volumio volumio[27883]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Dec 10 09:30:49 volumio volumio[27883]: info: Updating MyVolumio device info
Dec 10 09:30:49 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:49 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:49 volumio volumio[27883]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Dec 10 09:30:50 volumio volumio[27883]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Dec 10 09:30:51 volumio volumio[27883]: info: Getting Spotify volume
Dec 10 09:30:51 volumio volumio[27883]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 10 09:30:51 volumio volumio[27883]: Error: connect ECONNREFUSED 127.0.0.1:9879
Dec 10 09:30:51 volumio volumio[27883]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) {
Dec 10 09:30:51 volumio volumio[27883]: errno: -111,
Dec 10 09:30:51 volumio volumio[27883]: code: 'ECONNREFUSED',
Dec 10 09:30:51 volumio volumio[27883]: syscall: 'connect',
Dec 10 09:30:51 volumio volumio[27883]: address: '127.0.0.1',
Dec 10 09:30:51 volumio volumio[27883]: port: 9879,
Dec 10 09:30:51 volumio volumio[27883]: response: undefined
Dec 10 09:30:51 volumio volumio[27883]: }
Dec 10 09:30:51 volumio volumio[27883]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 10 09:30:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6.
Dec 10 09:30:51 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:51 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Dec 10 09:30:51 volumio go-librespot[28432]: go-librespot daemon starting...
Dec 10 09:30:51 volumio go-librespot[28433]: time="2025-12-10T09:30:51-06:00" level=info msg="running go-librespot 0.4.0"
Dec 10 09:30:51 volumio go-librespot[28433]: time="2025-12-10T09:30:51-06:00" level=debug msg="app state loaded"
Dec 10 09:30:51 volumio go-librespot[28433]: time="2025-12-10T09:30:51-06:00" level=debug msg="stored credentials not found"
Dec 10 09:30:51 volumio go-librespot[28433]: time="2025-12-10T09:30:51-06:00" level=info msg="api server listening on 127.0.0.1:9879"
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=info msg="zeroconf server listening on port 37335"
Dec 10 09:30:52 volumio sudo[28443]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-10 09:29'
Dec 10 09:30:52 volumio sudo[28443]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=debug msg="obtained new client token: AACQwmXLP7hgWnt/7o4xEGIHkhnGBze7DpHOuiPIvBRA80LLBTLr23ZrcFEOJ1ujJiHXGxY/2E9pL/bgJqnO/zxfALeqSvpCiUiAzLEK3UyTdsE+Hgmww6ajN4BJznzfn6+sUPLAInJh5vGGyCgfNihXINPAD7STHx7Esn4FFuLqDdfm+1O0oT6zDxhKx/slOCSoIdLqyN5JqNgpYeC3oymDBoxS6fCzzSBwORJUd2KxMCdlYpq9wrEpew=="
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070"
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=debug msg="completed keyexchange"
Dec 10 09:30:52 volumio go-librespot[28433]: time="2025-12-10T09:30:52-06:00" level=debug msg="completed challenge"
PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)"
NAME="Raspbian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
VOLUMIO_BUILD_VERSION="ac7dd5922ede329d1459d48b226ddc71f5209a2c"
VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd"
VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2"
VOLUMIO_BE_VERSION="3441cddd43405c36fe444484553f10f2f5bc830b"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Thu Nov 13 11:04:27 UTC 2025"
VOLUMIO_VERSION="4.069"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="7da8d6d9f8baf8621af4ec2af5a00f00"