Dec 08 11:29:00 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:00 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 47. Dec 08 11:29:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:01 volumio go-librespot[8460]: go-librespot daemon starting... Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=debug msg="app state loaded" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-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 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-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 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-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 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=info msg="zeroconf server listening on port 37817" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=debug msg="obtained new client token: AABA2hkqSL4jwqTTrFZHZpRDjL0FoaU8HH522PKFS94ap29LWmtjMW13uTKK5yBNikn8QO+wfMDc6BZCA3wI+JL5eILjKDUquKc/pFovOj+SkZ7XHOtAKfZLcFP7WU7DGIejyBBFAOA4TQlEGo/6G/hmrhYV/DlP65RSNT56g9BEGDqRC4BfZEF7ZPy9ugkh3wLQxMwxBJ3LKfE5RieJvFCwFt8r3H9nIxWvkjH3eBwX4yjECHgHLayTtA==" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-06:00" level=debug msg="completed challenge" Dec 08 11:29:01 volumio go-librespot[8461]: time="2025-12-08T11:29:01-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 08 11:29:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:03 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:03 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:04 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:04 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:04 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Dec 08 11:29:04 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Dec 08 11:29:04 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Dec 08 11:29:04 volumio volumio[7867]: info: CoreCommandRouter::volumioGetBrowseSources Dec 08 11:29:04 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 11:29:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48. Dec 08 11:29:04 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:04 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:04 volumio go-librespot[8483]: go-librespot daemon starting... Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=debug msg="app state loaded" Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-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 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-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 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-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 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=info msg="zeroconf server listening on port 37877" Dec 08 11:29:05 volumio volumio[7867]: error: MyVolumio Plugin failed to authenticate in a timely fashion Dec 08 11:29:05 volumio volumio[7867]: info: Completed starting MyVolumio Plugin Dec 08 11:29:05 volumio volumio[7867]: [Metrics] CommandRouter: 53s 914.54ms Dec 08 11:29:05 volumio volumio[7867]: info: CoreCommandRouter::volumiosetStartupVolume Dec 08 11:29:05 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:05 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=debug msg="obtained new client token: AADYoqZ8Lzwzfv2dhnKNlQwnULM8BSukCfpPw739UNoanzmxRuNS14qfzXOtOhEPvek03JUZovaSL2AMwoXZOkw56mzeCoMr71vVb2D1EEQYqprpnsuO4GVoWfhWU59c7sOs17oRjD9kPc5+v+oP9cne57fcX6sFPtXzd/4SQlCFUEf7gVkO1u8CQPWlz9bkTNaqYUQCS1peHcBP5QIY3yUZKJexU44pahFg3ADOsUlKYqyg+7JLapHdEQ==" Dec 08 11:29:05 volumio volumio[7867]: info: CoreCommandRouter::Close All Modals sent Dec 08 11:29:05 volumio volumio[7867]: info: CoreCommandRouter::Close All Modals sent Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29:05-06:00" level=debug msg="completed challenge" Dec 08 11:29:05 volumio go-librespot[8484]: time="2025-12-08T11:29: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 08 11:29:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:06 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Dec 08 11:29:06 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Dec 08 11:29:06 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Dec 08 11:29:06 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:06 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49. Dec 08 11:29:08 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:08 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:08 volumio go-librespot[8497]: go-librespot daemon starting... Dec 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-06:00" level=debug msg="app state loaded" Dec 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-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 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-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 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-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 08 11:29:08 volumio go-librespot[8498]: time="2025-12-08T11:29:08-06:00" level=info msg="zeroconf server listening on port 36447" Dec 08 11:29:09 volumio go-librespot[8498]: time="2025-12-08T11:29:09-06:00" level=debug msg="obtained new client token: AAAeyogvTDQBW4iHNRx2mCZgj+Et2qyoODNxDI6hHreqhsFRtkx/iTm9kdjjZTs+hV9HMgTWHN02nSJ/VtZGY+ymHCZIM/YcQtE/VR7BTeg1IucbCS/PrCN/63nRZD9Cx1oBHTyLL2mPNOIoJfMlACQzZFucDVFKQYRggU/WqboYzIrf/AQlGXag5W09Kskp6xoOAKAi4dPZkydutdq8aZIkaNDvDv7NASTyJwfxuV4DlH1/JfBpDeg=" Dec 08 11:29:09 volumio go-librespot[8498]: time="2025-12-08T11:29:09-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:09 volumio go-librespot[8498]: time="2025-12-08T11:29:09-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:09 volumio go-librespot[8498]: time="2025-12-08T11:29:09-06:00" level=debug msg="completed challenge" Dec 08 11:29:09 volumio go-librespot[8498]: time="2025-12-08T11:29: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 08 11:29:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:09 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:09 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:12 volumio volumio[7867]: info: BOOT COMPLETED Dec 08 11:29:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50. Dec 08 11:29:12 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:12 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:12 volumio go-librespot[8505]: go-librespot daemon starting... Dec 08 11:29:12 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:12 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=debug msg="app state loaded" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29: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-gew4.spotify.com:80]" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-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 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-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 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=info msg="zeroconf server listening on port 34267" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=debug msg="obtained new client token: AACeDBj2DQjex1Hnf06X5Ud7pWmByLhPjByTOT7qNGuG+EO2LVfp1Ibt3me1niWsskfYKxtOyT9AcwgLMnEBmi8okkuuNM7NPi9ALd6h4BChtZcwx80upYxX/Sa69WCBvWe62E8985TiTljLyaGjbf6FlgWfllvTXFG2jjasVE/3oj8frmRiPFtHxWajnnE8fRyOrWPjlkZvLcp+t5LVO3fw12frHAyyDrExVwXkESARare1CMgNKY92Bw==" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-06:00" level=debug msg="completed challenge" Dec 08 11:29:12 volumio go-librespot[8506]: time="2025-12-08T11:29:12-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 08 11:29:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:15 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:15 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 51. Dec 08 11:29:16 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:16 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:16 volumio go-librespot[8530]: go-librespot daemon starting... Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=debug msg="app state loaded" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29: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 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29: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 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29: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 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=info msg="zeroconf server listening on port 36421" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=debug msg="obtained new client token: AAA+jfRMgkzGvZx/frfhW/DoHKHJnqV3NQDOmkhReP0dcNfPo6/MXODpr6lsxGm81X/NlPQJfFMGXC/m1+ik2Lx6eZUeus203DTVaGL4oT+Ny7M2U23UuwV8UYU4+pk31dJ5Aoh7jfU6azlRgjV99UJY3zGFedz3xvo8+OViRPT76Q6KeyddPjYIklwTYsVLWi7aUFbr0uqrkrcVYK4N3KRUuxCuCA1MLM/RsVVwbMFfotHNIHNDhqgz+A==" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-06:00" level=debug msg="completed challenge" Dec 08 11:29:16 volumio go-librespot[8531]: time="2025-12-08T11:29:16-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 08 11:29:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:18 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:18 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 52. Dec 08 11:29:19 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:19 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:19 volumio go-librespot[8538]: go-librespot daemon starting... Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=debug msg="app state loaded" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-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 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-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 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-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 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=info msg="zeroconf server listening on port 40293" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=debug msg="obtained new client token: AAC6FSvAcVdE+YRHCUiT5O5Y++6U5pOmnRj2JgtDcVcUAlCOS3x7/x3c7bAzvJK8PB2RnquQmUlGdiv87OIJk2wh0dQ0JlIuqx+eLftyfISUd/s4PD/PDHBghaQdQCbKLYlqOkjq/oVRpjuX1gP/4OvxB5yb8cUPeKUX3P5zFS2S67Ob5IywmzmS6iygotO9GVnGKq6fhB0n+fKy5QHrkjyCIiNVOt3OHabB5Hs/18W2BivVmX5GITR1Qg==" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-06:00" level=debug msg="completed challenge" Dec 08 11:29:20 volumio go-librespot[8539]: time="2025-12-08T11:29:20-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 08 11:29:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:21 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:21 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 53. Dec 08 11:29:23 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:23 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:23 volumio go-librespot[8546]: go-librespot daemon starting... Dec 08 11:29:23 volumio go-librespot[8547]: time="2025-12-08T11:29:23-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:23 volumio go-librespot[8547]: time="2025-12-08T11:29:23-06:00" level=debug msg="app state loaded" Dec 08 11:29:23 volumio go-librespot[8547]: time="2025-12-08T11:29:23-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:23 volumio go-librespot[8547]: time="2025-12-08T11:29:23-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29: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-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-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 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-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 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-06:00" level=info msg="zeroconf server listening on port 35133" Dec 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-06:00" level=debug msg="obtained new client token: AACcDDxvusoovfvTp7J1trawOjzC4sJZ9nVUmAslaKn9aVP+j3gBUkIl+2y76t0KGpPx3EGBrhkvLZvdH0krWQqb2dFYDMAf6rcmo0W4R+1qcC50wnI4Oe2AXSGGyNoS4HxLq0aC3gJDnYgSWyhlvAbtHvEqpQCH1CFEZ9qiUwluBZXiIfqaVJfrL7eQt4wcCa24rrc6mdoodH5qivfheXC5wBDeeRt7FlA5/YIOWYTXpY1+d8W+1j4=" Dec 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-06:00" level=debug msg="completed challenge" Dec 08 11:29:24 volumio go-librespot[8547]: time="2025-12-08T11:29:24-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 08 11:29:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:24 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:24 volumio volumio[7867]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:26 volumio volumio[7867]: info: UPDATER: Scheduling automatic update Dec 08 11:29:26 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: system , getAutoUpdateWindowStartTime Dec 08 11:29:26 volumio volumio[7867]: info: CoreCommandRouter::executeOnPlugin: system , getAutoUpdateWindowStopTime Dec 08 11:29:26 volumio volumio[7867]: info: UPDATER: Auto update will take place at: Tue Dec 09 2025 03:22:49 GMT-0600 (Central Standard Time) Dec 08 11:29:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 54. Dec 08 11:29:27 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:27 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:27 volumio go-librespot[8569]: go-librespot daemon starting... Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=debug msg="app state loaded" Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:27 volumio volumio[7867]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=debug msg="new websocket client" Dec 08 11:29:27 volumio volumio[7867]: info: Connection to go-librespot Websocket established Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-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 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-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 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-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 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=info msg="zeroconf server listening on port 34089" Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=debug msg="obtained new client token: AAD5yIVez6BMwVatP3Oh5ggqXmVw4ufRd2idpKPhYx975/WE/gYTQdxomaXicwFebe+PxxnB3o5sBETOLM/vcKESpyC2AsoVu4iQ7d8dxG60uVJiGYqLgOQE6lT3TpAgfZyhf/bvnyBxVtODvZR62neSQ/QFLBUfQy+iQKimDuHXaPJJmtopMRhZfyIz90JUJPSl2wA8nA5wObJ3399wnam5PKfGCP0wzEj3TAzQ2vkXtagR3VtqRwRn9w==" Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:27 volumio go-librespot[8570]: time="2025-12-08T11:29:27-06:00" level=debug msg="completed challenge" Dec 08 11:29:28 volumio go-librespot[8570]: time="2025-12-08T11:29:28-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 08 11:29:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:28 volumio volumio[7867]: info: Connection to go-librespot Websocket closed Dec 08 11:29:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:30 volumio volumio[7867]: info: Getting Spotify volume Dec 08 11:29:30 volumio volumio[7867]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 11:29:30 volumio volumio[7867]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:30 volumio volumio[7867]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 08 11:29:30 volumio volumio[7867]: errno: -111, Dec 08 11:29:30 volumio volumio[7867]: code: 'ECONNREFUSED', Dec 08 11:29:30 volumio volumio[7867]: syscall: 'connect', Dec 08 11:29:30 volumio volumio[7867]: address: '127.0.0.1', Dec 08 11:29:30 volumio volumio[7867]: port: 9879, Dec 08 11:29:30 volumio volumio[7867]: response: undefined Dec 08 11:29:30 volumio volumio[7867]: } Dec 08 11:29:30 volumio volumio[7867]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 11:29:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55. Dec 08 11:29:31 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:31 volumio go-librespot[8589]: go-librespot daemon starting... Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=debug msg="app state loaded" Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:31 volumio sudo[8598]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 11:28' Dec 08 11:29:31 volumio sudo[8598]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:31 volumio sudo[8598]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:31 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:31 volumio volumio-remote-updater[9752]: [2025-12-08 11:29:31] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 08 11:29:31 volumio volumio-remote-updater[9752]: [2025-12-08 11:29:31] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 08 11:29:31 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 08 11:29:31 volumio systemd[1]: volumio.service: Consumed 50.516s CPU time. Dec 08 11:29:31 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-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 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-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 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-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 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=info msg="zeroconf server listening on port 45349" Dec 08 11:29:31 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=debug msg="obtained new client token: AAD/KT67aYWmduk/CZh8qGGI+KABv0Gr+d6dcX9WzouAveWQFV4Q4DhEOuomr1X9WcZ8xEvg1dW/qHrNMwneis41pyD8+g4XPeemjNncrZfk75dfMLFGCWFJibn8r4LwikZmlE8j6AlGF5LpqZIrBJJqkK2YMLOMra2YK/upyEJsmyATcHInRifOOCPZyyUxMeo8QggbDbFWc7jvdbsUOfmn4BgoH1Z5Hs+CMkcvSWYuAqXjKlCi71ubJQ==" Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:31 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 23233. Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:31 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 08 11:29:31 volumio go-librespot[8590]: time="2025-12-08T11:29:31-06:00" level=debug msg="completed challenge" Dec 08 11:29:31 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 08 11:29:31 volumio systemd[1]: volumio.service: Consumed 50.516s CPU time. Dec 08 11:29:32 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 08 11:29:32 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 08 11:29:32 volumio go-librespot[8590]: time="2025-12-08T11:29:32-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 08 11:29:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:33 volumio volumio[8615]: info: ------------------------------------------- Dec 08 11:29:33 volumio volumio[8615]: info: ----- Volumio3 ---- Dec 08 11:29:33 volumio volumio[8615]: info: ------------------------------------------- Dec 08 11:29:33 volumio volumio[8615]: info: ----- System startup ---- Dec 08 11:29:33 volumio volumio[8615]: info: ------------------------------------------- Dec 08 11:29:34 volumio volumio[8615]: info: MYVOLUMIO Environment detected Dec 08 11:29:34 volumio volumio[8615]: info: Plugin folders cleanup Dec 08 11:29:34 volumio volumio[8615]: info: Scanning into folder /volumio/app/plugins/ Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category audio_interface Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category miscellanea Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category music_service Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category plugins.json Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category system_controller Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category user_interface Dec 08 11:29:34 volumio volumio[8615]: info: Scanning into folder /data/plugins/ Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category audio_interface Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category music_service Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category system_controller Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category system_hardware Dec 08 11:29:34 volumio volumio[8615]: info: Scanning category user_interface Dec 08 11:29:34 volumio volumio[8615]: info: Plugin folders cleanup completed Dec 08 11:29:34 volumio volumio[8615]: info: ------------------------------------------- Dec 08 11:29:34 volumio volumio[8615]: info: ----- Core plugins startup ---- Dec 08 11:29:34 volumio volumio[8615]: info: ------------------------------------------- Dec 08 11:29:34 volumio volumio[8615]: info: Loading plugins from folder /volumio/app/plugins/ Dec 08 11:29:34 volumio volumio[8615]: info: Adding plugin upnp to MyMusic Plugins Dec 08 11:29:34 volumio volumio[8615]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 08 11:29:34 volumio volumio[8615]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 08 11:29:34 volumio volumio[8615]: info: Loading plugins from folder /data/plugins/ Dec 08 11:29:34 volumio volumio[8615]: info: Loading plugin "system"... Dec 08 11:29:34 volumio volumio[8615]: info: Loading plugin "appearance"... Dec 08 11:29:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56. Dec 08 11:29:35 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:35 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:35 volumio go-librespot[8642]: go-librespot daemon starting... Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=debug msg="app state loaded" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-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 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-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 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-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 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=info msg="zeroconf server listening on port 44993" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=debug msg="obtained new client token: AADD4og3uEa1f0dlITo18Hkkb1J3bCSmXNFF5psMDTctk1XfxEPLHsRKKZRvA7QJNltGSOnQA6Qib6shpHgHThULZm0k116HnhwOeM2M46/NBH9K8ECJiehiQEaaebwMroZ4tTuPpjxOAUTZlBHM4lFH5xYeuzWJMiesAaTBBUjcXiqaH5rm61Z+Rtdzwko8JBLPWuowRdR4+pLCRyi3YqMG54H3rjsxLn0VNAFkw+WxXjIWSURzySEnNQ==" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-06:00" level=debug msg="completed challenge" Dec 08 11:29:35 volumio go-librespot[8643]: time="2025-12-08T11:29:35-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 08 11:29:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "network"... Dec 08 11:29:36 volumio volumio[8615]: info: Refreshing Cached IP Addresses Dec 08 11:29:36 volumio sudo[8654]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 11:29:36 volumio sudo[8654]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:36 volumio sudo[8656]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 11:29:36 volumio sudo[8656]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "services"... Dec 08 11:29:36 volumio sudo[8656]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:36 volumio sudo[8654]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "alsa_controller"... Dec 08 11:29:36 volumio sudo[8664]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 08 11:29:36 volumio sudo[8664]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:36 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "wizard"... Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "networkfs"... Dec 08 11:29:36 volumio volumio[8615]: info: Starting Udev Watcher for removable devices Dec 08 11:29:36 volumio volumio[8615]: info: Ignoring mount for partition: boot Dec 08 11:29:36 volumio volumio[8615]: info: Ignoring mount for partition: volumio Dec 08 11:29:36 volumio volumio[8615]: info: Ignoring mount for partition: volumio_data Dec 08 11:29:36 volumio volumio[8615]: info: Mounting Device Wikipedia Dec 08 11:29:36 volumio sudo[8693]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 08 11:29:36 volumio sudo[8693]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:36 volumio sudo[8693]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:36 volumio volumio[8615]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 08 11:29:36 volumio volumio[8615]: dmesg(1) may have more information after failed mount system call. Dec 08 11:29:36 volumio volumio[8615]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 08 11:29:36 volumio volumio[8615]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 08 11:29:36 volumio volumio[8615]: dmesg(1) may have more information after failed mount system call. Dec 08 11:29:36 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "volumio_command_line_client"... Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "upnp"... Dec 08 11:29:36 volumio volumio[8615]: info: [1765214976317] Starting Upmpd Daemon Dec 08 11:29:36 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "my_music"... Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "mpd"... Dec 08 11:29:36 volumio volumio-remote-updater[9752]: [2025-12-08 11:29:36] [connect] Successful connection Dec 08 11:29:36 volumio volumio[8615]: info: Loading plugin "upnp_browser"... Dec 08 11:29:36 volumio sudo[8664]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:38 volumio volumio[8615]: info: Loading plugin "alarm-clock"... Dec 08 11:29:38 volumio volumio[8615]: info: Loading plugin "airplay_emulation"... Dec 08 11:29:38 volumio volumio[8615]: info: Starting Shairport Sync Dec 08 11:29:38 volumio volumio[8615]: info: Loading plugin "last_100"... Dec 08 11:29:38 volumio volumio[8615]: info: Loading plugin "webradio"... Dec 08 11:29:38 volumio volumio[8615]: info: Loading plugin "i2s_dacs"... Dec 08 11:29:38 volumio volumio[8615]: info: I2S DAC not set, start Auto-detection Dec 08 11:29:38 volumio volumio[8615]: info: Loading plugin "volumiodiscovery"... Dec 08 11:29:38 volumio volumio[8615]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 08 11:29:38 volumio volumio[8615]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:29:38 volumio volumio[8615]: *** WARNING *** For more information see Dec 08 11:29:38 volumio volumio[8615]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 08 11:29:38 volumio volumio[8615]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:29:38 volumio volumio[8615]: *** WARNING *** For more information see Dec 08 11:29:38 volumio node[8615]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 08 11:29:38 volumio node[8615]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:29:38 volumio node[8615]: *** WARNING *** For more information see Dec 08 11:29:38 volumio node[8615]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 08 11:29:38 volumio node[8615]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:29:38 volumio node[8615]: *** WARNING *** For more information see Dec 08 11:29:38 volumio volumio[8615]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 08 11:29:38 volumio volumio[8615]: info: Discovery: Started advertising with name: Volumio Dec 08 11:29:38 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 11:29:38 volumio volumio[8615]: info: Loading plugin "bandcamp"... Dec 08 11:29:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57. Dec 08 11:29:38 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:39 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:39 volumio go-librespot[8697]: go-librespot daemon starting... Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=debug msg="app state loaded" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-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 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-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 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-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 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=info msg="zeroconf server listening on port 39943" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=debug msg="obtained new client token: AABWPTh7VbiVSPaD1n37qszKqdKclmQrkKSrXGD7Yu5YfaGibiNS7+iyw6vyqi9gQsAxcjWssCip+q0qsllYFNyOFmTCSIez+2zZA/7Lrhd4yX2vGm/PJg6Ww7C37L/lSh8pkESZHgBJJEgjvLJnc7EXu8qwCKKst0wXRooAfeud0O4X19+ykRJ2rUweJF8ywuKtQQEJfrcnXGggKkObzODW92BKh1nE1zAdRkXvI4WKZrrWuc6Uuxdfaw==" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-06:00" level=debug msg="completed challenge" Dec 08 11:29:39 volumio go-librespot[8698]: time="2025-12-08T11:29:39-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 08 11:29:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:39 volumio volumio[8615]: info: Plugin calmradio is not enabled Dec 08 11:29:39 volumio volumio[8615]: info: Loading plugin "soundcloud"... Dec 08 11:29:40 volumio volumio[8615]: info: Loading plugin "spop"... Dec 08 11:29:41 volumio volumio[8615]: info: Loading plugin "squeezelite_mc"... Dec 08 11:29:41 volumio volumio[8615]: info: Loading plugin "youtube2"... Dec 08 11:29:42 volumio volumio[8615]: info: Loading plugin "ytcr"... Dec 08 11:29:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 58. Dec 08 11:29:42 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:42 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:42 volumio go-librespot[8705]: go-librespot daemon starting... Dec 08 11:29:42 volumio go-librespot[8706]: time="2025-12-08T11:29:42-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:42 volumio go-librespot[8706]: time="2025-12-08T11:29:42-06:00" level=debug msg="app state loaded" Dec 08 11:29:42 volumio go-librespot[8706]: time="2025-12-08T11:29:42-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:42 volumio go-librespot[8706]: time="2025-12-08T11:29:42-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-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 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-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 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-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 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-06:00" level=info msg="zeroconf server listening on port 35695" Dec 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-06:00" level=debug msg="obtained new client token: AADhpIqqmGDMS/4DaGWdSUYF9za79y5VjXxGvIVixIZYeZ9nxcWo3XgwJcKtOQE0xNI8aHBGehLkLTCd+kdlWmncFoQGAfjOv8k8hOMl4NbRsicOgxJ8tPnpVns1DLmqZq0F1D62mECjHCH7wrlq9zZNibTiF97WWtRXWj86VhYK0xWAhRG/AFzCRj84/x2WBSFgQsXyNr7bAtIMMv9Lsol6jz5MgRkSruiXUSOuSBWSvawbwHGfXNI=" Dec 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-06:00" level=debug msg="completed challenge" Dec 08 11:29:43 volumio go-librespot[8706]: time="2025-12-08T11:29:43-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 08 11:29:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:43 volumio volumio[8615]: info: Loading plugin "ytmusic"... Dec 08 11:29:44 volumio volumio[8615]: info: Plugin now_playing is not enabled Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "outputs"... Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "albumart"... Dec 08 11:29:44 volumio volumio[8615]: info: Plugin example_plugin is not enabled Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "inputs"... Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "updater_comm"... Dec 08 11:29:44 volumio volumio[8615]: info: Plugin mpdemulation is not enabled Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "rest_api"... Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "websocket"... Dec 08 11:29:44 volumio volumio[8615]: info: Starting Socket.io Server version 1.7.4 Dec 08 11:29:44 volumio volumio[8615]: info: Plugin fusiondsp is not enabled Dec 08 11:29:44 volumio volumio[8615]: info: Plugin mpdoutput is not enabled Dec 08 11:29:44 volumio volumio[8615]: info: Plugin RoonBridge is not enabled Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "podcast"... Dec 08 11:29:44 volumio volumio[8615]: info: ControllerPodcast::constructor Dec 08 11:29:44 volumio volumio[8615]: info: Loading plugin "volusonic"... Dec 08 11:29:44 volumio volumio[8714]: Forking 3 albumart workers Dec 08 11:29:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 59. Dec 08 11:29:46 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:46 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:46 volumio go-librespot[8768]: go-librespot daemon starting... Dec 08 11:29:46 volumio volumio[8726]: Starting albumart workers Dec 08 11:29:46 volumio volumio[8615]: info: Applying required configuration parameters for plugin volusonic Dec 08 11:29:46 volumio volumio[8725]: Starting albumart workers Dec 08 11:29:46 volumio volumio[8615]: info: Loading plugin "backup_restore"... Dec 08 11:29:46 volumio go-librespot[8769]: time="2025-12-08T11:29:46-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:46 volumio go-librespot[8769]: time="2025-12-08T11:29:46-06:00" level=debug msg="app state loaded" Dec 08 11:29:46 volumio go-librespot[8769]: time="2025-12-08T11:29:46-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:46 volumio go-librespot[8769]: time="2025-12-08T11:29:46-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:46 volumio volumio[8724]: Starting albumart workers Dec 08 11:29:46 volumio volumio[8615]: info: Applying required configuration parameters for plugin backup_restore Dec 08 11:29:46 volumio volumio[8615]: info: Plugin rpi_eeprom_config is not enabled Dec 08 11:29:46 volumio volumio[8615]: info: Plugin rpi_eeprom_updater is not enabled Dec 08 11:29:46 volumio volumio[8615]: info: Loading plugin "scheduledrestart"... Dec 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-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 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-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 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-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 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-06:00" level=info msg="zeroconf server listening on port 46079" Dec 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-06:00" level=debug msg="obtained new client token: AAAGt6KRX5D7kIEBZQSJDANLzK42vKXSKq/BGekGBaMXEB30LsVwqdm3fTCdGPdHNN/gPDXugTV2s4+hooZX8c83VGTOKFGxtUllP60Iu1RjCQlt3mTje7g0SuLuhpFZntvpVlDqnzpDNLAwK72rzvPV2oufTVwQrW3N9kPskZs00ILn2iDIrbiBUoqGJLKQWI69pzgp/VOLsUO/SS3YCqWIiLeOhOgbFS98nJ+EkljnjwxiDvrJb8U=" Dec 08 11:29:47 volumio volumio[8615]: info: Applying required configuration parameters for plugin scheduledrestart Dec 08 11:29:47 volumio volumio[8615]: info: Plugin Bluetoothremote is not enabled Dec 08 11:29:47 volumio volumio[8615]: info: Plugin music_services_shield is not enabled Dec 08 11:29:47 volumio volumio[8615]: info: Loading plugin "Systeminfo"... Dec 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-06:00" level=debug msg="completed challenge" Dec 08 11:29:47 volumio go-librespot[8769]: time="2025-12-08T11:29:47-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 08 11:29:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:47 volumio volumio[8615]: info: Plugin peppymeterbasic is not enabled Dec 08 11:29:47 volumio volumio[8615]: info: Loading plugin "peppyspectrum"... Dec 08 11:29:47 volumio volumio[8615]: info: Loading i18n strings for locale en Dec 08 11:29:47 volumio volumio[8615]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 08 11:29:47 volumio volumio[8615]: Updating browse sources language Dec 08 11:29:47 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::initPlayerControls Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: Express server listening on port 3000 Dec 08 11:29:48 volumio volumio[8615]: [Metrics] WebUI: 14s 678.26ms Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::resetVolumioState Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::getcurrentVolume Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioRetrievevolume Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:48 volumio sudo[8799]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 11:29:48 volumio sudo[8799]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:48 volumio sudo[8799]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:48 volumio sudo[8801]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 11:29:48 volumio sudo[8801]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:48 volumio sudo[8801]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:48 volumio volumio[8615]: info: Volumio Network Manager: Network status updated: 1 Dec 08 11:29:48 volumio volumio[8615]: info: VolumeController:: Volume=86 Mute =false Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::pushState Dec 08 11:29:48 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioPushState Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::updateTrackBlock Dec 08 11:29:48 volumio volumio[8615]: info: CorePlayQueue::getTrackBlock Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioRetrievevolume Dec 08 11:29:48 volumio volumio[8615]: info: Reloading queue from file Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::setRepeat null single undefined Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::pushState Dec 08 11:29:48 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioPushState Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::setRandom null Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::pushState Dec 08 11:29:48 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioPushState Dec 08 11:29:48 volumio volumio[8615]: info: Setting Device type: Raspberry PI Dec 08 11:29:48 volumio volumio[8615]: info: VolumeController:: Volume=86 Mute =false Dec 08 11:29:48 volumio volumio[8615]: info: CoreStateMachine::pushState Dec 08 11:29:48 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioPushState Dec 08 11:29:48 volumio sudo[8815]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 08 11:29:48 volumio sudo[8815]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:48 volumio volumio[8615]: info: Completed loading Core Plugins Dec 08 11:29:48 volumio volumio[8615]: info: Preparing to generate the ALSA configuration file Dec 08 11:29:48 volumio volumio[8615]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 08 11:29:48 volumio volumio[8615]: info: Reading ALSA contributions from plugins. Dec 08 11:29:48 volumio volumio[8615]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 08 11:29:48 volumio volumio[8615]: info: Discovery: Found device Volumio Dec 08 11:29:48 volumio sudo[8815]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioGetState Dec 08 11:29:48 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:48 volumio volumio[8615]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 08 11:29:48 volumio volumio[8615]: info: Discovery: Found device Volumio Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioGetState Dec 08 11:29:48 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:48 volumio volumio[8615]: info: Upmpdcli Daemon Started Dec 08 11:29:48 volumio volumio[8615]: info: Asound.conf file unchanged, so no further update is needed Dec 08 11:29:48 volumio volumio[8615]: info: Output device has changed, restarting MPD Dec 08 11:29:48 volumio volumio[8615]: info: Output device has changed, restarting Shairport Sync Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:48 volumio sudo[8818]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 11:29:48 volumio sudo[8818]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:48 volumio sudo[8820]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 11:29:48 volumio sudo[8820]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:48 volumio sudo[8818]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:48 volumio volumio[8615]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:29:48 volumio volumio[8615]: info: ___________ START PLUGINS ___________ Dec 08 11:29:48 volumio volumio[8615]: info: ControllerMpd::onStart: Initializing MPD Dec 08 11:29:48 volumio volumio[8615]: info: Creating MPD Configuration file Dec 08 11:29:48 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 08 11:29:48 volumio sudo[8828]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 11:29:48 volumio sudo[8828]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:48 volumio volumio[8615]: info: [1765214988692] CoreMusicLibrary::Adding element Media Servers Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:48 volumio sudo[8828]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:48 volumio sudo[8830]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 11:29:48 volumio sudo[8830]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:48 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 08 11:29:48 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 08 11:29:48 volumio systemd[1]: mpd.service: Consumed 4.524s CPU time. Dec 08 11:29:48 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 08 11:29:48 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 08 11:29:48 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 08 11:29:48 volumio volumio[8615]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:48 volumio volumio[8615]: info: [1765214988802] CoreMusicLibrary::Adding element Last_100 Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:48 volumio volumio[8615]: info: [1765214988807] CoreMusicLibrary::Adding element Webradio Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 11:29:48 volumio volumio[8615]: info: Initializing BBC Radios Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:48 volumio volumio[8615]: info: [1765214988876] CoreMusicLibrary::Adding element Bandcamp Discover Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:48 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:48 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 08 11:29:48 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:48 volumio volumio[8615]: info: [1765214988893] CoreMusicLibrary::Adding element SoundCloud Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:48 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:48 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:48 volumio volumio[8615]: info: Creating Spotify config file Dec 08 11:29:48 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio sudo[8855]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 08 11:29:49 volumio sudo[8855]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 08 11:29:49 volumio sudo[8855]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:49 volumio volumio-remote-updater[9752]: [2025-12-08 11:29:49] [connect] Successful connection Dec 08 11:29:49 volumio volumio[8615]: info: [squeezelite_mc] Starting proxy server... Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:49 volumio volumio[8615]: info: [1765214989255] CoreMusicLibrary::Adding element YouTube2 Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube2 Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:49 volumio volumio[8615]: info: [1765214989274] CoreMusicLibrary::Adding element YouTube Music Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube2 Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube Music Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:49 volumio volumio[8615]: info: [1765214989286] CoreMusicLibrary::Adding element Podcast Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube2 Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube Music Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Podcast Dec 08 11:29:49 volumio volumio[8615]: info: Loading i18n strings for locale en Dec 08 11:29:49 volumio volumio[8615]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 08 11:29:49 volumio volumio[8615]: Updating browse sources language Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube2 Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube Music Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Podcast Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube2 Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube Music Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Podcast Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:49 volumio volumio[8615]: info: [1765214989333] CoreMusicLibrary::Adding element Volusonic Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube2 Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source YouTube Music Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Podcast Dec 08 11:29:49 volumio volumio[8615]: Cannot find translation for source Volusonic Dec 08 11:29:49 volumio volumio[8615]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 08 11:29:49 volumio volumio[8615]: info: Volumio Calling Home Dec 08 11:29:49 volumio volumio[8615]: info: [squeezelite_mc] Proxy server started on port 33731 Dec 08 11:29:49 volumio volumio[8615]: info: Preparing to generate the ALSA configuration file Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::volumioRetrievevolume Dec 08 11:29:49 volumio volumio[8615]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 08 11:29:49 volumio volumio[8615]: info: Reading ALSA contributions from plugins. Dec 08 11:29:49 volumio volumio[8615]: info: MPD Permissions set Dec 08 11:29:49 volumio volumio[8615]: info: MPD Permissions set Dec 08 11:29:49 volumio volumio-remote-updater[9752]: [2025-12-08 11:29:49] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765214989 101 Dec 08 11:29:49 volumio volumio[8615]: 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 08 11:29:49 volumio volumio[8615]: info: Spotify config file written Dec 08 11:29:49 volumio sudo[8865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 08 11:29:49 volumio sudo[8865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:49 volumio volumio[8615]: 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 08 11:29:49 volumio volumio[8615]: info: VolumeController:: Volume=86 Mute =false Dec 08 11:29:49 volumio volumio[8615]: info: CoreStateMachine::pushState Dec 08 11:29:49 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::volumioPushState Dec 08 11:29:49 volumio volumio[8615]: info: [squeezelite_mc] Server discovery started Dec 08 11:29:49 volumio volumio[8615]: info: [squeezelite_mc] Player finder started Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 08 11:29:49 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:49 volumio volumio[8615]: info: No need to fix Spotify hosts Dec 08 11:29:49 volumio go-librespot[8868]: go-librespot daemon starting... Dec 08 11:29:49 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:49 volumio sudo[8865]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:49 volumio go-librespot[8880]: time="2025-12-08T11:29:49-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:49 volumio go-librespot[8880]: time="2025-12-08T11:29:49-06:00" level=debug msg="app state loaded" Dec 08 11:29:49 volumio go-librespot[8880]: time="2025-12-08T11:29:49-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:49 volumio go-librespot[8880]: time="2025-12-08T11:29:49-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:49 volumio volumio[8615]: 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 08 11:29:50 volumio volumio[8615]: 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 08 11:29:50 volumio volumio[8615]: info: Volumio called home Dec 08 11:29:50 volumio volumio[8615]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 08 11:29:50 volumio volumio[8615]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 08 11:29:50 volumio volumio[8615]: 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 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11: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-gew4.spotify.com:80]" Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11: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 gew4-dealer.spotify.com:443]" Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11: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 gew4-spclient.spotify.com:443]" Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11:29:50-06:00" level=info msg="zeroconf server listening on port 46287" Dec 08 11:29:50 volumio volumio[8615]: info: Starting Shairport Sync Dec 08 11:29:50 volumio volumio[8615]: info: Starting Shairport Sync Dec 08 11:29:50 volumio volumio[8615]: info: Starting Shairport Sync Dec 08 11:29:50 volumio sudo[8893]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:29:50 volumio sudo[8893]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio sudo[8894]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:29:50 volumio sudo[8894]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio sudo[8896]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:29:50 volumio sudo[8896]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11:29:50-06:00" level=debug msg="obtained new client token: AABDQgks9lQhrkwCCMiC12B4k9rmwNjuPpmXjOrBn6P7Dlaq/KArxuc2CxbmK4FU2G+4xM8MtQbMX3IHxo+L37hyri6ygQQzinZLufUIGNSaR7bLHZ8/lxnu0R8dgmdOi4yrXm/XphX95NG/H4UpkRv72nO0RvIwZw5R8UZt/Q8kZgnmye6dmuhOSOkZyoPu8XZADUtzFHcsJLHm8EyEORCCXW7wMva7V1YggwbBfNKploztJrLgN5w=" Dec 08 11:29:50 volumio volumio[8615]: info: Asound.conf file unchanged, so no further update is needed Dec 08 11:29:50 volumio volumio[8615]: info: Output device has changed, restarting MPD Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11:29:50-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:50 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 08 11:29:50 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 08 11:29:50 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:29:50 volumio systemd[1]: shairport-sync.service: Consumed 2.035s CPU time. Dec 08 11:29:50 volumio sudo[8889]: 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 08 11:29:50 volumio sudo[8889]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio volumio[8615]: info: Output device has changed, restarting Shairport Sync Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:50 volumio sudo[8889]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:50 volumio sudo[8901]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 11:29:50 volumio sudo[8901]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio sudo[8901]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11:29:50-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11:29:50-06:00" level=debug msg="completed challenge" Dec 08 11:29:50 volumio volumio[8615]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:29:50 volumio sudo[8905]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 11:29:50 volumio sudo[8905]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:29:50 volumio sudo[8896]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:50 volumio sudo[8894]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:50 volumio go-librespot[8880]: time="2025-12-08T11: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 08 11:29:50 volumio volumio[8615]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 11:29:50 volumio volumio[8615]: SPOTIFY: BQDCGA8sExHzmAoVTPJZ1Sk5L3odgxLbFgclelO7Ej5f6sAFCfhWyIEql8OBiGp6yJG6xgdfKgSQ4_7zzcOx814UJB-ZCT81Jf2jk49e7V_eoaTxMBr-YFwokCFbldIsLu3J4o-bN7d6br5wmwsu4yb45CxPUyCT0QdymxekYRXZMrBW0wQaZIqcOB0nt47E2js4hX7GZjDzrm1wrk8lEHlU2ouADIn-zvPaBFQ Dec 08 11:29:50 volumio volumio[8615]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 11:29:50 volumio sudo[8893]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:50 volumio volumio[8615]: info: New Spotify access token = BQDCGA8sExHzmAoVTPJZ1Sk5L3odgxLbFgclelO7Ej5f6sAFCfhWyIEql8OBiGp6yJG6xgdfKgSQ4_7zzcOx814UJB-ZCT81Jf2jk49e7V_eoaTxMBr-YFwokCFbldIsLu3J4o-bN7d6br5wmwsu4yb45CxPUyCT0QdymxekYRXZMrBW0wQaZIqcOB0nt47E2js4hX7GZjDzrm1wrk8lEHlU2ouADIn-zvPaBFQ Dec 08 11:29:50 volumio volumio[8615]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 08 11:29:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:50 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 08 11:29:50 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 08 11:29:50 volumio systemd[1]: mpd.service: Consumed 1.536s CPU time. Dec 08 11:29:50 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 08 11:29:50 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 08 11:29:50 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 08 11:29:50 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 08 11:29:50 volumio volumio[8615]: info: MPD Permissions set Dec 08 11:29:50 volumio volumio[8615]: info: Shairport-Sync Started Dec 08 11:29:50 volumio volumio[8615]: Error adding Membership: Error: addMembership EINVAL Dec 08 11:29:50 volumio volumio[8615]: info: Shairport-Sync Started Dec 08 11:29:50 volumio volumio[8615]: info: Shairport-Sync Started Dec 08 11:29:50 volumio volumio[8615]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 08 11:29:50 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 08 11:29:50 volumio sudo[8933]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 08 11:29:50 volumio sudo[8933]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio sudo[8933]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:50 volumio volumio[8615]: 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 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:50 volumio sudo[8930]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 08 11:29:50 volumio sudo[8930]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 08 11:29:50 volumio sudo[8930]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:50 volumio volumio[8615]: info: CoreCommandRouter::volumioGetState Dec 08 11:29:50 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:50 volumio sudo[8938]: 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 08 11:29:50 volumio sudo[8938]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:50 volumio volumio[8615]: info: Starting Shairport Sync Dec 08 11:29:50 volumio sudo[8938]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:51 volumio sudo[8948]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:29:51 volumio sudo[8948]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:51 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 08 11:29:51 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 08 11:29:51 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 08 11:29:51 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:29:51 volumio volumio[8615]: 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 08 11:29:51 volumio volumio[8615]: info: Spotify Successfully logged in Dec 08 11:29:51 volumio sudo[8951]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 08 11:29:51 volumio sudo[8951]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:51 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:29:51 volumio volumio[8615]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:29:51 volumio volumio[8615]: info: [1765214991114] CoreMusicLibrary::Adding element Spotify Dec 08 11:29:51 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:29:51 volumio volumio[8615]: Cannot find translation for source Bandcamp Discover Dec 08 11:29:51 volumio volumio[8615]: Cannot find translation for source SoundCloud Dec 08 11:29:51 volumio volumio[8615]: Cannot find translation for source YouTube2 Dec 08 11:29:51 volumio volumio[8615]: Cannot find translation for source YouTube Music Dec 08 11:29:51 volumio volumio[8615]: Cannot find translation for source Podcast Dec 08 11:29:51 volumio volumio[8615]: Cannot find translation for source Volusonic Dec 08 11:29:51 volumio volumio[8615]: Cannot find translation for source Spotify Dec 08 11:29:51 volumio sudo[8948]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:51 volumio systemd[1]: Reloading. Dec 08 11:29:51 volumio volumio[8615]: info: Shairport-Sync Started Dec 08 11:29:51 volumio volumio[8615]: info: [squeezelite_mc] Notification listener started Dec 08 11:29:51 volumio volumio[8615]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 08 11:29:51 volumio volumio[8615]: 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 08 11:29:51 volumio volumio[8615]: 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 08 11:29:52 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:52 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:52 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:29:52 volumio volumio[8615]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:29:53 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 08 11:29:53 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 08 11:29:53 volumio volumio[8615]: info: go-librespot daemon successfully initialized Dec 08 11:29:53 volumio sudo[8951]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:53 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:29:53 volumio sudo[8986]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:29:53 volumio sudo[8986]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:53 volumio volumio[8615]: info: CoreCommandRouter::volumioGetState Dec 08 11:29:53 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:53 volumio sudo[8986]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:53 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 08 11:29:53 volumio sudo[8989]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 08 11:29:53 volumio sudo[8989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:53 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 08 11:29:53 volumio volumio[8615]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 08 11:29:53 volumio volumio[8615]: info: CoreCommandRouter::volumioGetState Dec 08 11:29:53 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 60. Dec 08 11:29:53 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:53 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:53 volumio go-librespot[8991]: go-librespot daemon starting... Dec 08 11:29:53 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 08 11:29:53 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 08 11:29:53 volumio go-librespot[8992]: time="2025-12-08T11:29:53-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:53 volumio go-librespot[8992]: time="2025-12-08T11:29:53-06:00" level=debug msg="app state loaded" Dec 08 11:29:53 volumio go-librespot[8992]: time="2025-12-08T11:29:53-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:53 volumio go-librespot[8992]: time="2025-12-08T11:29:53-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:53 volumio sudo[8989]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11: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-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11:29:54-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 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11:29:54-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 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11:29:54-06:00" level=info msg="zeroconf server listening on port 41911" Dec 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11:29:54-06:00" level=debug msg="obtained new client token: AAC+ouF+Sw+rS0L+LzBZeFp+efo0emOUILhZW0wm/M2XJq0bOt13MZBFSQ2rs8VFmc9nYXaiq07XAwGWUsZWDLb6lO/DVPD9DX6ivkiyQ2J4nfBM6o0xidLLBgn+izZQLwokEctgf3zlz/YgNegsVMkdpDRtWogwmhCaDBK0wwy5yhcxcu42TBqF55mOCkfvpZT/gb9ckGO2mPcPX9JFNMb+x4rgkqi/C6KUsYnXKDq3FKEEgxkjKNA=" Dec 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11:29:54-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11:29:54-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11:29:54-06:00" level=debug msg="completed challenge" Dec 08 11:29:54 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:29:54 volumio go-librespot[8992]: time="2025-12-08T11: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 08 11:29:54 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:54 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:54 volumio sudo[9000]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:29:54 volumio sudo[9000]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:54 volumio sudo[9000]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:54 volumio volumio[8615]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 08 11:29:54 volumio sudo[9004]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 08 11:29:54 volumio sudo[9004]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:54 volumio sudo[9004]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:54 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 08 11:29:54 volumio sudo[9007]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 08 11:29:54 volumio sudo[9007]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:54 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 08 11:29:54 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 08 11:29:54 volumio sudo[9007]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:54 volumio volumio[8615]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 08 11:29:54 volumio volumio[8615]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 08 11:29:54 volumio volumio[8615]: 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 08 11:29:54 volumio volumio[8615]: 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 08 11:29:54 volumio mpd[8945]: 2025-12-08T11:29:54 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 08 11:29:54 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 08 11:29:55 volumio sudo[8830]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:55 volumio sudo[8820]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:55 volumio sudo[8905]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:55 volumio volumio[8615]: error: MPD error: The expression evaluated to a falsy value: Dec 08 11:29:55 volumio volumio[8615]: assert.ok(self.idling) Dec 08 11:29:55 volumio volumio[8615]: error: The expression evaluated to a falsy value: Dec 08 11:29:55 volumio volumio[8615]: assert.ok(self.idling) Dec 08 11:29:55 volumio volumio[8615]: error: MPD error: The expression evaluated to a falsy value: Dec 08 11:29:55 volumio volumio[8615]: assert.ok(self.idling) Dec 08 11:29:55 volumio volumio[8615]: error: The expression evaluated to a falsy value: Dec 08 11:29:55 volumio volumio[8615]: assert.ok(self.idling) Dec 08 11:29:55 volumio volumio[8615]: info: MPD running with PID8945 Dec 08 11:29:55 volumio volumio[8615]: ,establishing connection Dec 08 11:29:55 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:29:55 volumio volumio[8615]: error: updateQueue error: null Dec 08 11:29:55 volumio volumio[8615]: error: updateQueue error: null Dec 08 11:29:55 volumio sudo[9018]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:29:55 volumio sudo[9018]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:55 volumio sudo[9018]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:55 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:29:55 volumio sudo[9021]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:29:55 volumio sudo[9021]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:55 volumio volumio[8615]: info: CoreCommandRouter::volumioGetState Dec 08 11:29:55 volumio volumio[8615]: info: CorePlayQueue::getTrack 0 Dec 08 11:29:55 volumio sudo[9021]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:56 volumio volumio[8615]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:56 volumio volumio[8615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:29:56 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:29:56 volumio sudo[9041]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:29:56 volumio sudo[9041]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:56 volumio sudo[9041]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:56 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:29:56 volumio sudo[9044]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:29:56 volumio sudo[9044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:57 volumio sudo[9044]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 61. Dec 08 11:29:57 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:57 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:29:57 volumio go-librespot[9046]: go-librespot daemon starting... Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=debug msg="app state loaded" Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=debug msg="stored credentials not found" Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:29:57 volumio volumio[8615]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:29:57 volumio sudo[9054]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:29:57 volumio sudo[9054]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:57 volumio sudo[9054]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:57 volumio volumio[8615]: info: Completed starting Core Plugins Dec 08 11:29:57 volumio volumio[8615]: info: ------------------------------------------- Dec 08 11:29:57 volumio volumio[8615]: info: ----- MyVolumio plugins startup ---- Dec 08 11:29:57 volumio volumio[8615]: info: ------------------------------------------- Dec 08 11:29:57 volumio volumio[8615]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-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 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-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 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-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 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=info msg="zeroconf server listening on port 36111" Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=debug msg="obtained new client token: AABNlATC+6SGlAqal/NxOegXFlMB27o5V2QuRL0GZ0p1WBTUHqAEbQ8I/yU68prsXhQ70EEi2iXiH3IEAh3ZKGB7m9iqMiGrNco+C78BJTVNjSZ699WXIhpMfQklFB/fJWRCPP71da8PQkvf/1L4b2X7yErWXGNTXHkqm+qaVVX4sWpP5Bd9Ex0ibZJUqrza2+71+FMuGzSWc873U55QFl47tJXDjjISxGPLJOHnyDKGHgjuoeGCEkF3Ew==" Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=debug msg="completed keyexchange" Dec 08 11:29:57 volumio go-librespot[9047]: time="2025-12-08T11:29:57-06:00" level=debug msg="completed challenge" Dec 08 11:29:58 volumio go-librespot[9047]: time="2025-12-08T11:29:58-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 08 11:29:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:29:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:29:58 volumio sudo[9059]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 11:29:58 volumio sudo[9059]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:58 volumio sudo[9061]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 11:29:58 volumio sudo[9061]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:58 volumio sudo[9063]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 11:29:58 volumio sudo[9063]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:29:58 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 08 11:29:58 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 08 11:29:58 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 08 11:29:58 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 08 11:29:58 volumio mpd_monitor.sh[9067]: MPD Monitor Service: Starting MPD Monitor Service Dec 08 11:29:58 volumio sudo[9061]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:58 volumio sudo[9059]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:58 volumio volumio[8615]: info: Successfully started MPD Monitor Dec 08 11:29:58 volumio sudo[9063]: pam_unix(sudo:session): session closed for user root Dec 08 11:29:58 volumio volumio[8615]: info: Successfully started MPD Monitor Dec 08 11:29:58 volumio volumio[8615]: info: Successfully started MPD Monitor Dec 08 11:29:59 volumio volumio[8615]: info: Initializing connection to go-librespot Websocket Dec 08 11:29:59 volumio volumio[8615]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:30:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 62. Dec 08 11:30:01 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:01 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:01 volumio go-librespot[9071]: go-librespot daemon starting... Dec 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-06:00" level=debug msg="app state loaded" Dec 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-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 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-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 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-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 08 11:30:01 volumio go-librespot[9072]: time="2025-12-08T11:30:01-06:00" level=info msg="zeroconf server listening on port 38723" Dec 08 11:30:02 volumio go-librespot[9072]: time="2025-12-08T11:30:02-06:00" level=debug msg="obtained new client token: AAATRY1gnFQVmBRwnDbuLgmiRO8xkcPygybTemJ7BWNrtSVJAGyWUMoWllRzkHT97N+9OXT/jfkZH2jbKlkoGoiufWmxRDWrm7dqsNB1IUgT3Utkv8Sopx50nDAfIpOYWn6IU0mBPAHi6WUZAr9zX/XjaWLbo6aBhdV4JUsAnv9dGe6lPqrYacIy8N1jybxsbF8vseIJnCtdrlQm4glv+7681GRxdEk8B0u1oCC3aASbvlxHnlrwMoVOsw==" Dec 08 11:30:02 volumio volumio[8615]: info: Initializing connection to go-librespot Websocket Dec 08 11:30:02 volumio go-librespot[9072]: time="2025-12-08T11:30:02-06:00" level=debug msg="new websocket client" Dec 08 11:30:02 volumio volumio[8615]: info: Connection to go-librespot Websocket established Dec 08 11:30:02 volumio go-librespot[9072]: time="2025-12-08T11:30:02-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:02 volumio go-librespot[9072]: time="2025-12-08T11:30:02-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:02 volumio go-librespot[9072]: time="2025-12-08T11:30:02-06:00" level=debug msg="completed challenge" Dec 08 11:30:02 volumio go-librespot[9072]: time="2025-12-08T11:30:02-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 08 11:30:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:02 volumio volumio[8615]: info: Connection to go-librespot Websocket closed Dec 08 11:30:05 volumio volumio[8615]: info: Getting Spotify volume Dec 08 11:30:05 volumio volumio[8615]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 11:30:05 volumio volumio[8615]: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:30:05 volumio volumio[8615]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Dec 08 11:30:05 volumio volumio[8615]: errno: -111, Dec 08 11:30:05 volumio volumio[8615]: code: 'ECONNREFUSED', Dec 08 11:30:05 volumio volumio[8615]: syscall: 'connect', Dec 08 11:30:05 volumio volumio[8615]: address: '127.0.0.1', Dec 08 11:30:05 volumio volumio[8615]: port: 9879, Dec 08 11:30:05 volumio volumio[8615]: response: undefined Dec 08 11:30:05 volumio volumio[8615]: } Dec 08 11:30:05 volumio volumio[8615]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 11:30:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 63. Dec 08 11:30:05 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:06 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:06 volumio go-librespot[9091]: go-librespot daemon starting... Dec 08 11:30:06 volumio go-librespot[9093]: time="2025-12-08T11:30:06-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:06 volumio go-librespot[9093]: time="2025-12-08T11:30:06-06:00" level=debug msg="app state loaded" Dec 08 11:30:06 volumio go-librespot[9093]: time="2025-12-08T11:30:06-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:06 volumio go-librespot[9093]: time="2025-12-08T11:30:06-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:06 volumio sudo[9116]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 11:29' Dec 08 11:30:06 volumio sudo[9116]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:06 volumio sudo[9116]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:06 volumio volumio-remote-updater[9752]: [2025-12-08 11:30:06] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 08 11:30:06 volumio volumio-remote-updater[9752]: [2025-12-08 11:30:06] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 08 11:30:06 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:06 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 08 11:30:06 volumio systemd[1]: volumio.service: Consumed 42.103s CPU time. Dec 08 11:30:06 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 08 11:30:06 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-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 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-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 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-06:00" level=info msg="zeroconf server listening on port 32855" Dec 08 11:30:07 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 23234. Dec 08 11:30:07 volumio systemd[1]: Started dynamicswap.service - dynamicswap service. Dec 08 11:30:07 volumio systemd[1]: Stopped volumio.service - Volumio Backend Module. Dec 08 11:30:07 volumio systemd[1]: volumio.service: Consumed 42.103s CPU time. Dec 08 11:30:07 volumio systemd[1]: Started volumio.service - Volumio Backend Module. Dec 08 11:30:07 volumio systemd[1]: dynamicswap.service: Deactivated successfully. Dec 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-06:00" level=debug msg="obtained new client token: AABJ8pUd5wiTMY2Q3XU4eItmTBbgKGOvHH+d0SACPyCQMR32iC5YXWlyFGYucJGB02BbzQd8Gq1wwISwM+sPZWcAcgSwZ3XHJqPnP8ygxVoFvoROO55KdCqOWJbxmAYieSvscaXbKDQM6gd6OWAnq09SkqErk2rnZwB51RYhAQDZbC7iiWwXW9pI4wHc3Exd26FbqXQIfKsIZztBYjbKtHEA5nXJuDcvGif1tqfNu0aqTVZha0iYRZbNOA==" Dec 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-06:00" level=debug msg="completed challenge" Dec 08 11:30:07 volumio go-librespot[9093]: time="2025-12-08T11:30:07-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 08 11:30:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:09 volumio volumio[9128]: info: ------------------------------------------- Dec 08 11:30:09 volumio volumio[9128]: info: ----- Volumio3 ---- Dec 08 11:30:09 volumio volumio[9128]: info: ------------------------------------------- Dec 08 11:30:09 volumio volumio[9128]: info: ----- System startup ---- Dec 08 11:30:09 volumio volumio[9128]: info: ------------------------------------------- Dec 08 11:30:09 volumio volumio[9128]: info: MYVOLUMIO Environment detected Dec 08 11:30:10 volumio volumio[9128]: info: Plugin folders cleanup Dec 08 11:30:10 volumio volumio[9128]: info: Scanning into folder /volumio/app/plugins/ Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category audio_interface Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category miscellanea Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category music_service Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category plugins.json Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category system_controller Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category user_interface Dec 08 11:30:10 volumio volumio[9128]: info: Scanning into folder /data/plugins/ Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category audio_interface Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category music_service Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category system_controller Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category system_hardware Dec 08 11:30:10 volumio volumio[9128]: info: Scanning category user_interface Dec 08 11:30:10 volumio volumio[9128]: info: Plugin folders cleanup completed Dec 08 11:30:10 volumio volumio[9128]: info: ------------------------------------------- Dec 08 11:30:10 volumio volumio[9128]: info: ----- Core plugins startup ---- Dec 08 11:30:10 volumio volumio[9128]: info: ------------------------------------------- Dec 08 11:30:10 volumio volumio[9128]: info: Loading plugins from folder /volumio/app/plugins/ Dec 08 11:30:10 volumio volumio[9128]: info: Adding plugin upnp to MyMusic Plugins Dec 08 11:30:10 volumio volumio[9128]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 08 11:30:10 volumio volumio[9128]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 08 11:30:10 volumio volumio[9128]: info: Loading plugins from folder /data/plugins/ Dec 08 11:30:10 volumio volumio[9128]: info: Loading plugin "system"... Dec 08 11:30:10 volumio volumio[9128]: info: Loading plugin "appearance"... Dec 08 11:30:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 64. Dec 08 11:30:10 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:11 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:11 volumio go-librespot[9155]: go-librespot daemon starting... Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=debug msg="app state loaded" Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "network"... Dec 08 11:30:11 volumio volumio[9128]: info: Refreshing Cached IP Addresses Dec 08 11:30:11 volumio sudo[9164]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 11:30:11 volumio sudo[9164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:11 volumio sudo[9164]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:11 volumio sudo[9166]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "services"... Dec 08 11:30:11 volumio sudo[9166]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "alsa_controller"... Dec 08 11:30:11 volumio sudo[9174]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 08 11:30:11 volumio sudo[9174]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:11 volumio sudo[9166]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-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 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-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 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=info msg="zeroconf server listening on port 42265" Dec 08 11:30:11 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "wizard"... Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "networkfs"... Dec 08 11:30:11 volumio volumio[9128]: info: Starting Udev Watcher for removable devices Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=debug msg="obtained new client token: AAC2q6ENGS0Z7OGTJychuUIsQvTDP4AFaSNZqn7Gffx4n1LpTudMjl6P7jwIk06/erbn52NneLlSn3h+4KbDDZtaQmLQjafaVNHqmwe8zuxp4DnT1ufiLLZSrJcYdrAnpMgenDraYNUWn/cMxKZZ7DeOc6qVxGMyIZVYGJo/oTwdp09NW7ND9NTagaCm9JE99AUtBYGbTQBnwePKpd2ISp7f1ZwfxV2L6xurOsp4y6QEEIXjJkRQtAxXmg==" Dec 08 11:30:11 volumio volumio[9128]: info: Ignoring mount for partition: boot Dec 08 11:30:11 volumio volumio[9128]: info: Ignoring mount for partition: volumio Dec 08 11:30:11 volumio volumio[9128]: info: Ignoring mount for partition: volumio_data Dec 08 11:30:11 volumio volumio[9128]: info: Mounting Device Wikipedia Dec 08 11:30:11 volumio sudo[9203]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/Wikipedia -o noatime Dec 08 11:30:11 volumio sudo[9203]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:11 volumio sudo[9203]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:11 volumio volumio[9128]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 08 11:30:11 volumio volumio[9128]: dmesg(1) may have more information after failed mount system call. Dec 08 11:30:11 volumio volumio[9128]: error: Failed to mount Wikipedia: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/Wikipedia" -o noatime Dec 08 11:30:11 volumio volumio[9128]: mount: /media/Wikipedia: /dev/sda1 already mounted on /media/Wikipedia. Dec 08 11:30:11 volumio volumio[9128]: dmesg(1) may have more information after failed mount system call. Dec 08 11:30:11 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "volumio_command_line_client"... Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "upnp"... Dec 08 11:30:11 volumio volumio[9128]: info: [1765215011552] Starting Upmpd Daemon Dec 08 11:30:11 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "my_music"... Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "mpd"... Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30:11-06:00" level=debug msg="completed challenge" Dec 08 11:30:11 volumio go-librespot[9156]: time="2025-12-08T11:30: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 08 11:30:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:11 volumio volumio-remote-updater[9752]: [2025-12-08 11:30:11] [connect] Successful connection Dec 08 11:30:11 volumio sudo[9174]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:11 volumio volumio[9128]: info: Loading plugin "upnp_browser"... Dec 08 11:30:13 volumio volumio[9128]: info: Loading plugin "alarm-clock"... Dec 08 11:30:13 volumio volumio[9128]: info: Loading plugin "airplay_emulation"... Dec 08 11:30:13 volumio volumio[9128]: info: Starting Shairport Sync Dec 08 11:30:13 volumio volumio[9128]: info: Loading plugin "last_100"... Dec 08 11:30:13 volumio volumio[9128]: info: Loading plugin "webradio"... Dec 08 11:30:13 volumio volumio[9128]: info: Loading plugin "i2s_dacs"... Dec 08 11:30:13 volumio volumio[9128]: info: I2S DAC not set, start Auto-detection Dec 08 11:30:13 volumio volumio[9128]: info: Loading plugin "volumiodiscovery"... Dec 08 11:30:13 volumio volumio[9128]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 08 11:30:13 volumio volumio[9128]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:30:13 volumio volumio[9128]: *** WARNING *** For more information see Dec 08 11:30:13 volumio volumio[9128]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 08 11:30:13 volumio volumio[9128]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:30:13 volumio volumio[9128]: *** WARNING *** For more information see Dec 08 11:30:13 volumio node[9128]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 08 11:30:13 volumio node[9128]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:30:13 volumio node[9128]: *** WARNING *** For more information see Dec 08 11:30:13 volumio node[9128]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 08 11:30:13 volumio node[9128]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 08 11:30:13 volumio node[9128]: *** WARNING *** For more information see Dec 08 11:30:13 volumio volumio[9128]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 08 11:30:13 volumio volumio[9128]: info: Discovery: Started advertising with name: Volumio Dec 08 11:30:13 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 08 11:30:13 volumio volumio[9128]: info: Loading plugin "bandcamp"... Dec 08 11:30:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 65. Dec 08 11:30:14 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:14 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:14 volumio go-librespot[9207]: go-librespot daemon starting... Dec 08 11:30:14 volumio go-librespot[9208]: time="2025-12-08T11:30:14-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:14 volumio go-librespot[9208]: time="2025-12-08T11:30:14-06:00" level=debug msg="app state loaded" Dec 08 11:30:14 volumio go-librespot[9208]: time="2025-12-08T11:30:14-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:14 volumio go-librespot[9208]: time="2025-12-08T11:30:14-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:15 volumio volumio[9128]: info: Plugin calmradio is not enabled Dec 08 11:30:15 volumio volumio[9128]: info: Loading plugin "soundcloud"... Dec 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30:15-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 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30:15-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 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30:15-06:00" level=info msg="zeroconf server listening on port 43827" Dec 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30:15-06:00" level=debug msg="obtained new client token: AACSlXWaNGFLqqnirJ6dZ/K0Uwh0i/nvBn/ImLJvuCherrJ8kWWAMBAbjeKSBMyVsdKjDAHYZ05ULTE4Q61gYmyeIcpuRThoVC+9/9od+RpGKXfeEo1QCHgez9yghQikaoW7DQYVSmelYxC4EQwf2l4hQ7Ns5iiZ6APaOax4P+Hev+rDtHsww3GfYYN5Obgd3aqX9byjvcpkzvo6QYOcfwbPgKPH93mSXqGJG0Tx2QyjDS0IX24Hmhw=" Dec 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30:15-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30:15-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30:15-06:00" level=debug msg="completed challenge" Dec 08 11:30:15 volumio go-librespot[9208]: time="2025-12-08T11:30: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 08 11:30:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:15 volumio volumio[9128]: info: Loading plugin "spop"... Dec 08 11:30:16 volumio volumio[9128]: info: Loading plugin "squeezelite_mc"... Dec 08 11:30:17 volumio volumio[9128]: info: Loading plugin "youtube2"... Dec 08 11:30:17 volumio volumio[9128]: info: Loading plugin "ytcr"... Dec 08 11:30:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66. Dec 08 11:30:18 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:18 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:18 volumio go-librespot[9218]: go-librespot daemon starting... Dec 08 11:30:18 volumio go-librespot[9219]: time="2025-12-08T11:30:18-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:18 volumio go-librespot[9219]: time="2025-12-08T11:30:18-06:00" level=debug msg="app state loaded" Dec 08 11:30:18 volumio go-librespot[9219]: time="2025-12-08T11:30:18-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:18 volumio go-librespot[9219]: time="2025-12-08T11:30:18-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-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 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-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 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-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 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-06:00" level=info msg="zeroconf server listening on port 34285" Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "ytmusic"... Dec 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-06:00" level=debug msg="obtained new client token: AABQS+cmYc3/8RfGBxjZtWZhNc1+SbKidfZXNIvGUnE9LW76QQgJbyG6zxLJMfW8XFjHu14/GJqwdXjS1Ssuq7ZaSJJyYx+/Z8c52R8NF4FSa6Qq3kss6B2tKoETjimcJ/lD43+V6h1JWn4kB7yr9dJMeu2Kswqz0ZTh/AzVT1Emoifi9R40RireaXH2goSjpcWMgmgiD2KCMnpTp3XcGuo0pCOWxdLEv945Pb3iZsI7DMLnPF03AxM=" Dec 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30:19-06:00" level=debug msg="completed challenge" Dec 08 11:30:19 volumio go-librespot[9219]: time="2025-12-08T11:30: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 08 11:30:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:19 volumio volumio[9128]: info: Plugin now_playing is not enabled Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "outputs"... Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "albumart"... Dec 08 11:30:19 volumio volumio[9128]: info: Plugin example_plugin is not enabled Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "inputs"... Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "updater_comm"... Dec 08 11:30:19 volumio volumio[9128]: info: Plugin mpdemulation is not enabled Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "rest_api"... Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "websocket"... Dec 08 11:30:19 volumio volumio[9128]: info: Starting Socket.io Server version 1.7.4 Dec 08 11:30:19 volumio volumio[9128]: info: Plugin fusiondsp is not enabled Dec 08 11:30:19 volumio volumio[9128]: info: Plugin mpdoutput is not enabled Dec 08 11:30:19 volumio volumio[9128]: info: Plugin RoonBridge is not enabled Dec 08 11:30:19 volumio volumio[9128]: info: Loading plugin "podcast"... Dec 08 11:30:20 volumio volumio[9128]: info: ControllerPodcast::constructor Dec 08 11:30:20 volumio volumio[9128]: info: Loading plugin "volusonic"... Dec 08 11:30:20 volumio volumio[9226]: Forking 3 albumart workers Dec 08 11:30:21 volumio volumio[9128]: info: Applying required configuration parameters for plugin volusonic Dec 08 11:30:21 volumio volumio[9128]: info: Loading plugin "backup_restore"... Dec 08 11:30:21 volumio volumio[9236]: Starting albumart workers Dec 08 11:30:21 volumio volumio[9237]: Starting albumart workers Dec 08 11:30:21 volumio volumio[9128]: info: Applying required configuration parameters for plugin backup_restore Dec 08 11:30:21 volumio volumio[9128]: info: Plugin rpi_eeprom_config is not enabled Dec 08 11:30:21 volumio volumio[9128]: info: Plugin rpi_eeprom_updater is not enabled Dec 08 11:30:21 volumio volumio[9128]: info: Loading plugin "scheduledrestart"... Dec 08 11:30:22 volumio volumio[9238]: Starting albumart workers Dec 08 11:30:22 volumio volumio[9128]: info: Applying required configuration parameters for plugin scheduledrestart Dec 08 11:30:22 volumio volumio[9128]: info: Plugin Bluetoothremote is not enabled Dec 08 11:30:22 volumio volumio[9128]: info: Plugin music_services_shield is not enabled Dec 08 11:30:22 volumio volumio[9128]: info: Loading plugin "Systeminfo"... Dec 08 11:30:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67. Dec 08 11:30:22 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:22 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:22 volumio go-librespot[9280]: go-librespot daemon starting... Dec 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30:22-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30:22-06:00" level=debug msg="app state loaded" Dec 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30:22-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30:22-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:22 volumio volumio[9128]: info: Plugin peppymeterbasic is not enabled Dec 08 11:30:22 volumio volumio[9128]: info: Loading plugin "peppyspectrum"... Dec 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30: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 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30: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 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30: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 08 11:30:22 volumio go-librespot[9291]: time="2025-12-08T11:30:22-06:00" level=info msg="zeroconf server listening on port 39095" Dec 08 11:30:23 volumio go-librespot[9291]: time="2025-12-08T11:30:23-06:00" level=debug msg="obtained new client token: AABY7jqhU/gx6VNwj4uklQJUY9Nxmk35fwHZaiJmhMfYRd5G+lB3+QZ2nMByJ+QENN8+HyzTekA/BEOuVJRlGfbBwj687HJQaQX+vaog2DaXwwICVr/PBeID2gdtgxKSjTS99wfLx3EvWVa8kx4vD9hpD70aZ+BHkJUL0IJwaFORWrOF3OXLmIj6DvoPvdh9v9ga3dl0TpbB2aiN9fVHmyGK1vxEHPtzUyWCRHx7IKto3Qobj5SP1Wtk8A==" Dec 08 11:30:23 volumio volumio[9128]: info: Loading i18n strings for locale en Dec 08 11:30:23 volumio go-librespot[9291]: time="2025-12-08T11:30:23-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:23 volumio volumio[9128]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 08 11:30:23 volumio volumio[9128]: Updating browse sources language Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:23 volumio go-librespot[9291]: time="2025-12-08T11:30:23-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:23 volumio go-librespot[9291]: time="2025-12-08T11:30:23-06:00" level=debug msg="completed challenge" Dec 08 11:30:23 volumio go-librespot[9291]: time="2025-12-08T11:30: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 08 11:30:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::initPlayerControls Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: Express server listening on port 3000 Dec 08 11:30:23 volumio volumio[9128]: [Metrics] WebUI: 14s 581.83ms Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::resetVolumioState Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::getcurrentVolume Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioRetrievevolume Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:23 volumio sudo[9311]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 08 11:30:23 volumio sudo[9311]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:23 volumio sudo[9313]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 08 11:30:23 volumio sudo[9313]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:23 volumio sudo[9311]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:23 volumio sudo[9313]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:23 volumio volumio[9128]: info: Volumio Network Manager: Network status updated: 1 Dec 08 11:30:23 volumio volumio[9128]: info: VolumeController:: Volume=86 Mute =false Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::pushState Dec 08 11:30:23 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioPushState Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::updateTrackBlock Dec 08 11:30:23 volumio volumio[9128]: info: CorePlayQueue::getTrackBlock Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioRetrievevolume Dec 08 11:30:23 volumio volumio[9128]: info: Reloading queue from file Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::setRepeat null single undefined Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::pushState Dec 08 11:30:23 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioPushState Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::setRandom null Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::pushState Dec 08 11:30:23 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioPushState Dec 08 11:30:23 volumio volumio[9128]: info: Setting Device type: Raspberry PI Dec 08 11:30:23 volumio volumio[9128]: info: VolumeController:: Volume=86 Mute =false Dec 08 11:30:23 volumio volumio[9128]: info: CoreStateMachine::pushState Dec 08 11:30:23 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioPushState Dec 08 11:30:23 volumio volumio[9128]: info: Completed loading Core Plugins Dec 08 11:30:23 volumio volumio[9128]: info: Preparing to generate the ALSA configuration file Dec 08 11:30:23 volumio sudo[9326]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 08 11:30:23 volumio sudo[9326]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:23 volumio volumio[9128]: info: Discovery: adding a135e40e-a404-457b-98f5-36bf71c75954 Dec 08 11:30:23 volumio volumio[9128]: info: Discovery: Found device Volumio Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:23 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:23 volumio volumio[9128]: info: Discovery: this is already registered, a135e40e-a404-457b-98f5-36bf71c75954 Dec 08 11:30:23 volumio volumio[9128]: info: Discovery: Found device Volumio Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:23 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:23 volumio volumio[9128]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 08 11:30:23 volumio sudo[9326]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:23 volumio volumio[9128]: info: Reading ALSA contributions from plugins. Dec 08 11:30:23 volumio volumio[9128]: info: Upmpdcli Daemon Started Dec 08 11:30:23 volumio volumio[9128]: info: Asound.conf file unchanged, so no further update is needed Dec 08 11:30:23 volumio volumio[9128]: info: Output device has changed, restarting MPD Dec 08 11:30:23 volumio volumio[9128]: info: Output device has changed, restarting Shairport Sync Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:23 volumio sudo[9329]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 11:30:23 volumio sudo[9329]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:23 volumio sudo[9329]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:23 volumio sudo[9331]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 11:30:23 volumio sudo[9331]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:23 volumio volumio[9128]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:30:23 volumio volumio[9128]: info: ___________ START PLUGINS ___________ Dec 08 11:30:23 volumio volumio[9128]: info: ControllerMpd::onStart: Initializing MPD Dec 08 11:30:23 volumio volumio[9128]: info: Creating MPD Configuration file Dec 08 11:30:23 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:30:23 volumio sudo[9339]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:23 volumio volumio[9128]: info: [1765215023846] CoreMusicLibrary::Adding element Media Servers Dec 08 11:30:23 volumio sudo[9339]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:23 volumio sudo[9339]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:23 volumio sudo[9341]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 11:30:23 volumio sudo[9341]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:23 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 08 11:30:23 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 08 11:30:23 volumio systemd[1]: mpd.service: Consumed 4.644s CPU time. Dec 08 11:30:23 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 08 11:30:23 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 08 11:30:23 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 08 11:30:23 volumio volumio[9128]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:23 volumio volumio[9128]: info: [1765215023959] CoreMusicLibrary::Adding element Last_100 Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:23 volumio volumio[9128]: info: [1765215023963] CoreMusicLibrary::Adding element Webradio Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:23 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 11:30:23 volumio volumio[9128]: info: Initializing BBC Radios Dec 08 11:30:23 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 08 11:30:23 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:24 volumio volumio[9128]: info: [1765215024058] CoreMusicLibrary::Adding element Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:24 volumio volumio[9128]: info: [1765215024069] CoreMusicLibrary::Adding element SoundCloud Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:24 volumio volumio[9128]: info: Creating Spotify config file Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio sudo[9356]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 08 11:30:24 volumio sudo[9356]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 08 11:30:24 volumio sudo[9356]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:24 volumio volumio-remote-updater[9752]: [2025-12-08 11:30:24] [connect] Successful connection Dec 08 11:30:24 volumio volumio[9128]: info: [squeezelite_mc] Starting proxy server... Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:24 volumio volumio[9128]: info: [1765215024422] CoreMusicLibrary::Adding element YouTube2 Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube2 Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:24 volumio volumio[9128]: info: [1765215024445] CoreMusicLibrary::Adding element YouTube Music Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube2 Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube Music Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:24 volumio volumio[9128]: info: [1765215024457] CoreMusicLibrary::Adding element Podcast Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube2 Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube Music Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Podcast Dec 08 11:30:24 volumio volumio[9128]: info: Loading i18n strings for locale en Dec 08 11:30:24 volumio volumio[9128]: info: Plugin peppyspectrum has duplicated i18n key SAVE. It is ignored. Dec 08 11:30:24 volumio volumio[9128]: Updating browse sources language Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube2 Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube Music Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Podcast Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube2 Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube Music Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Podcast Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:24 volumio volumio[9128]: info: [1765215024505] CoreMusicLibrary::Adding element Volusonic Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube2 Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source YouTube Music Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Podcast Dec 08 11:30:24 volumio volumio[9128]: Cannot find translation for source Volusonic Dec 08 11:30:24 volumio volumio[9128]: info: Scheduling reboots with hours: 0, minutes: 0 in timezone: America/Chicago Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Dec 08 11:30:24 volumio volumio[9128]: info: Volumio Calling Home Dec 08 11:30:24 volumio volumio[9128]: info: [squeezelite_mc] Proxy server started on port 40269 Dec 08 11:30:24 volumio volumio[9128]: info: Preparing to generate the ALSA configuration file Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioRetrievevolume Dec 08 11:30:24 volumio volumio[9128]: info: The plugin peppyspectrum has an ALSA contribution file peppy_in.peppy_out.6.conf Dec 08 11:30:24 volumio volumio[9128]: info: Reading ALSA contributions from plugins. Dec 08 11:30:24 volumio volumio[9128]: info: MPD Permissions set Dec 08 11:30:24 volumio volumio[9128]: info: MPD Permissions set Dec 08 11:30:24 volumio volumio-remote-updater[9752]: [2025-12-08 11:30:24] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1765215024 101 Dec 08 11:30:24 volumio volumio[9128]: 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 08 11:30:24 volumio volumio[9128]: info: Spotify config file written Dec 08 11:30:24 volumio sudo[9377]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 08 11:30:24 volumio volumio[9128]: 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 08 11:30:24 volumio sudo[9377]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:24 volumio volumio[9128]: info: VolumeController:: Volume=86 Mute =false Dec 08 11:30:24 volumio volumio[9128]: info: CoreStateMachine::pushState Dec 08 11:30:24 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::volumioPushState Dec 08 11:30:24 volumio volumio[9128]: info: [squeezelite_mc] Server discovery started Dec 08 11:30:24 volumio volumio[9128]: info: [squeezelite_mc] Player finder started Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Dec 08 11:30:24 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:24 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:25 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:25 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:25 volumio volumio[9128]: info: No need to fix Spotify hosts Dec 08 11:30:25 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:25 volumio go-librespot[9381]: go-librespot daemon starting... Dec 08 11:30:25 volumio sudo[9377]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=debug msg="app state loaded" Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:25 volumio volumio[9128]: 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 08 11:30:25 volumio volumio[9128]: 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 08 11:30:25 volumio volumio[9128]: info: [squeezelite_mc] Card 1 supports the following ALSA formats: ["U8","S16_LE"] Dec 08 11:30:25 volumio volumio[9128]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"1","mixerType":"Hardware","mixer":"PCM"} Dec 08 11:30:25 volumio volumio[9128]: 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 08 11:30:25 volumio volumio[9128]: info: Volumio called home Dec 08 11:30:25 volumio volumio[9128]: info: Starting Shairport Sync Dec 08 11:30:25 volumio sudo[9400]: 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 08 11:30:25 volumio sudo[9400]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:25 volumio sudo[9400]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:25 volumio volumio[9128]: info: Starting Shairport Sync Dec 08 11:30:25 volumio volumio[9128]: info: Starting Shairport Sync Dec 08 11:30:25 volumio sudo[9406]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:30:25 volumio sudo[9406]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:25 volumio sudo[9408]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:30:25 volumio sudo[9408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:25 volumio sudo[9410]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:30:25 volumio sudo[9410]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:25 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 08 11:30:25 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 08 11:30:25 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:30:25 volumio systemd[1]: shairport-sync.service: Consumed 1.826s CPU time. Dec 08 11:30:25 volumio volumio[9128]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 11:30:25 volumio volumio[9128]: SPOTIFY: BQCkC5u9d8DfL7y2OeYcPS4PleInL8YOUlI6bTr40kj90_av7hsrp7evQ7KJg-gKpzkXCTKdwq9rhLOAPITMFvlW1h-V6pDguiKHgopDquOBPKuBNILz1XopLXCQCk5Opzddl1vwTVQrZlKlOYCqiouc6y9BwZfc0doonDbdbedzySjWyZtVLNpXG4dwNbfUNhPnZGBJx01BFvMEbO1_0fhamk029yKnbAncdm4 Dec 08 11:30:25 volumio volumio[9128]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 08 11:30:25 volumio volumio[9128]: info: New Spotify access token = BQCkC5u9d8DfL7y2OeYcPS4PleInL8YOUlI6bTr40kj90_av7hsrp7evQ7KJg-gKpzkXCTKdwq9rhLOAPITMFvlW1h-V6pDguiKHgopDquOBPKuBNILz1XopLXCQCk5Opzddl1vwTVQrZlKlOYCqiouc6y9BwZfc0doonDbdbedzySjWyZtVLNpXG4dwNbfUNhPnZGBJx01BFvMEbO1_0fhamk029yKnbAncdm4 Dec 08 11:30:25 volumio volumio[9128]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-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 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-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 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-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 08 11:30:25 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:30:25 volumio volumio[9128]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=info msg="zeroconf server listening on port 42159" Dec 08 11:30:25 volumio sudo[9408]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:25 volumio volumio[9128]: info: Asound.conf file unchanged, so no further update is needed Dec 08 11:30:25 volumio volumio[9128]: info: Output device has changed, restarting MPD Dec 08 11:30:25 volumio sudo[9406]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:25 volumio sudo[9410]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:25 volumio volumio[9128]: info: Output device has changed, restarting Shairport Sync Dec 08 11:30:25 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:25 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:25 volumio sudo[9419]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Dec 08 11:30:25 volumio sudo[9419]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=debug msg="obtained new client token: AADExb0YVf649Q9HTcYKNYivs8SkrA8Kx2ej6MFTc0vHdTPh1PfLRWIe3CqVJCYAyDwD5pUtmGXSfyLDusUqkcAWCZtJh9p6Ji4G+8z3PlOXCJksFVG5YWh+B0C8IiI3cSpf879iRjVPOAuhKlJRExkmD19mzVH4X/kjheSqJoiA1ggouLciX3PrI01xH8kW/jqSHAMYh0bpjIkp0mbmkiK5VTa146rhtSE63DZR2JZCY1pK9dD0EFkldA==" Dec 08 11:30:25 volumio sudo[9422]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Dec 08 11:30:25 volumio sudo[9417]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Dec 08 11:30:25 volumio sudo[9422]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:25 volumio sudo[9417]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:25 volumio volumio[9128]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Dec 08 11:30:25 volumio sudo[9419]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:25 volumio sudo[9417]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:25 volumio systemd[1]: mpd.service: Deactivated successfully. Dec 08 11:30:25 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. Dec 08 11:30:25 volumio systemd[1]: mpd.service: Consumed 1.725s CPU time. Dec 08 11:30:25 volumio systemd[1]: mpd.socket: Deactivated successfully. Dec 08 11:30:25 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Dec 08 11:30:25 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11:30:25-06:00" level=debug msg="completed challenge" Dec 08 11:30:25 volumio volumio[9128]: info: Shairport-Sync Started Dec 08 11:30:25 volumio volumio[9128]: Error adding Membership: Error: addMembership EINVAL Dec 08 11:30:25 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Dec 08 11:30:25 volumio go-librespot[9392]: time="2025-12-08T11: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 08 11:30:25 volumio systemd[1]: Starting mpd.service - Music Player Daemon... Dec 08 11:30:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:26 volumio volumio[9128]: info: MPD Permissions set Dec 08 11:30:26 volumio volumio[9128]: 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 08 11:30:26 volumio volumio[9128]: info: Shairport-Sync Started Dec 08 11:30:26 volumio volumio[9128]: info: Shairport-Sync Started Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:26 volumio sudo[9451]: 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 08 11:30:26 volumio sudo[9451]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:26 volumio sudo[9451]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:26 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:26 volumio sudo[9448]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Dec 08 11:30:26 volumio sudo[9448]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Dec 08 11:30:26 volumio sudo[9448]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:26 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Dec 08 11:30:26 volumio volumio[9128]: info: Starting Shairport Sync Dec 08 11:30:26 volumio sudo[9461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Dec 08 11:30:26 volumio sudo[9461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:26 volumio sudo[9463]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 08 11:30:26 volumio sudo[9463]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:26 volumio systemd[1]: Reloading. Dec 08 11:30:26 volumio volumio[9128]: 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 08 11:30:26 volumio volumio[9128]: info: Spotify Successfully logged in Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 08 11:30:26 volumio volumio[9128]: info: [1765215026404] CoreMusicLibrary::Adding element Spotify Dec 08 11:30:26 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 08 11:30:26 volumio volumio[9128]: Cannot find translation for source Bandcamp Discover Dec 08 11:30:26 volumio volumio[9128]: Cannot find translation for source SoundCloud Dec 08 11:30:26 volumio volumio[9128]: Cannot find translation for source YouTube2 Dec 08 11:30:26 volumio volumio[9128]: Cannot find translation for source YouTube Music Dec 08 11:30:26 volumio volumio[9128]: Cannot find translation for source Podcast Dec 08 11:30:26 volumio volumio[9128]: Cannot find translation for source Volusonic Dec 08 11:30:26 volumio volumio[9128]: Cannot find translation for source Spotify Dec 08 11:30:26 volumio volumio[9128]: info: [squeezelite_mc] Notification listener started Dec 08 11:30:26 volumio volumio[9128]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 08 11:30:27 volumio volumio[9128]: 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 08 11:30:27 volumio volumio[9128]: 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 08 11:30:27 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:27 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:27 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 08 11:30:27 volumio volumio[9128]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 08 11:30:28 volumio volumio[9128]: info: go-librespot daemon successfully initialized Dec 08 11:30:28 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:28 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:28 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 08 11:30:28 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 08 11:30:28 volumio sudo[9461]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:28 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:30:28 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 08 11:30:28 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 08 11:30:28 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:30:28 volumio systemd[1]: shairport-sync.service: Consumed 1.446s CPU time. Dec 08 11:30:28 volumio sudo[9485]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:30:28 volumio sudo[9485]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:28 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 08 11:30:28 volumio sudo[9463]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:28 volumio volumio[9128]: info: Shairport-Sync Started Dec 08 11:30:28 volumio sudo[9485]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:28 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Dec 08 11:30:28 volumio sudo[9502]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Dec 08 11:30:28 volumio sudo[9502]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:28 volumio systemd[1]: Stopping squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 08 11:30:28 volumio volumio[9128]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'disconnect' Dec 08 11:30:28 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:28 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:29 volumio systemd[1]: squeezelite.service: Deactivated successfully. Dec 08 11:30:29 volumio systemd[1]: Stopped squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 08 11:30:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 68. Dec 08 11:30:29 volumio sudo[9502]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:29 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:29 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:29 volumio go-librespot[9505]: go-librespot daemon starting... Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=debug msg="app state loaded" Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11: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 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11: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 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11: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 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=info msg="zeroconf server listening on port 45739" Dec 08 11:30:29 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:30:29 volumio sudo[9515]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:30:29 volumio sudo[9515]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=debug msg="obtained new client token: AABNEcSYB5YapMjehfLR88EKXzluZGRiporSkAcYrybgvsIOPwgpJ1ZilpCSm4+AqClnv3sm7xVJ1Gypy22AHmY8j2yMhu/jI1vOg901ph0v4iK8yHPJ9I66a9sKyTHQb9ymfe5qypVVR5kRwuomtWKdnisoV47UHAmBoKUkJjaEZjOtzECMCNIr3eeqgHD67q5+EjPh1aMqTxvm3VEJOp2Tbv+BDHsQmfKKIjBXNQFxFHWo8RdlEptUoA==" Dec 08 11:30:29 volumio sudo[9515]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:29 volumio volumio[9128]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Dec 08 11:30:29 volumio sudo[9519]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Dec 08 11:30:29 volumio sudo[9519]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:29 volumio sudo[9519]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:29 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Dec 08 11:30:29 volumio sudo[9522]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Dec 08 11:30:29 volumio sudo[9522]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11:30:29-06:00" level=debug msg="completed challenge" Dec 08 11:30:29 volumio go-librespot[9506]: time="2025-12-08T11: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 08 11:30:30 volumio systemd[1]: Starting squeezelite.service - Squeezelite lightweight headless Squeezebox emulator... Dec 08 11:30:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:30 volumio mpd[9459]: 2025-12-08T11:30:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 08 11:30:30 volumio systemd[1]: Started squeezelite.service - Squeezelite lightweight headless Squeezebox emulator. Dec 08 11:30:30 volumio sudo[9522]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:30 volumio volumio[9128]: info: [squeezelite_mc] 'client' notification received from BigBoss (192.168.1.180); type is 'connect' Dec 08 11:30:30 volumio volumio[9128]: info: [squeezelite_mc] Getting players connected to BigBoss (192.168.1.180) Dec 08 11:30:30 volumio volumio[9128]: 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 08 11:30:30 volumio volumio[9128]: 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 08 11:30:30 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 08 11:30:30 volumio sudo[9341]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:30 volumio sudo[9331]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:30 volumio sudo[9422]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:30 volumio volumio[9128]: error: MPD error: The expression evaluated to a falsy value: Dec 08 11:30:30 volumio volumio[9128]: assert.ok(self.idling) Dec 08 11:30:30 volumio volumio[9128]: error: The expression evaluated to a falsy value: Dec 08 11:30:30 volumio volumio[9128]: assert.ok(self.idling) Dec 08 11:30:30 volumio volumio[9128]: error: MPD error: The expression evaluated to a falsy value: Dec 08 11:30:30 volumio volumio[9128]: assert.ok(self.idling) Dec 08 11:30:30 volumio volumio[9128]: error: The expression evaluated to a falsy value: Dec 08 11:30:30 volumio volumio[9128]: assert.ok(self.idling) Dec 08 11:30:30 volumio volumio[9128]: info: MPD running with PID9459 Dec 08 11:30:30 volumio volumio[9128]: ,establishing connection Dec 08 11:30:30 volumio volumio[9128]: error: updateQueue error: null Dec 08 11:30:30 volumio volumio[9128]: error: updateQueue error: null Dec 08 11:30:30 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:30:30 volumio sudo[9533]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:30:30 volumio sudo[9533]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:30 volumio sudo[9533]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:31 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:30:31 volumio sudo[9536]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:30:31 volumio sudo[9536]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:31 volumio volumio[9128]: info: Initializing connection to go-librespot Websocket Dec 08 11:30:31 volumio volumio[9128]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 08 11:30:31 volumio sudo[9536]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:31 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:31 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:31 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:30:31 volumio sudo[9553]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:30:31 volumio sudo[9553]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:31 volumio sudo[9553]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:32 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:30:32 volumio sudo[9556]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:30:32 volumio sudo[9556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:32 volumio sudo[9556]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:32 volumio volumio[9128]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Dec 08 11:30:32 volumio sudo[9559]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Dec 08 11:30:32 volumio sudo[9559]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:33 volumio sudo[9559]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:33 volumio volumio[9128]: info: Completed starting Core Plugins Dec 08 11:30:33 volumio volumio[9128]: info: ------------------------------------------- Dec 08 11:30:33 volumio volumio[9128]: info: ----- MyVolumio plugins startup ---- Dec 08 11:30:33 volumio volumio[9128]: info: ------------------------------------------- Dec 08 11:30:33 volumio volumio[9128]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 08 11:30:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69. Dec 08 11:30:33 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:33 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:33 volumio go-librespot[9561]: go-librespot daemon starting... Dec 08 11:30:33 volumio go-librespot[9562]: time="2025-12-08T11:30:33-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:33 volumio go-librespot[9562]: time="2025-12-08T11:30:33-06:00" level=debug msg="app state loaded" Dec 08 11:30:33 volumio go-librespot[9562]: time="2025-12-08T11:30:33-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:33 volumio go-librespot[9562]: time="2025-12-08T11:30:33-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:33 volumio sudo[9569]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 11:30:33 volumio sudo[9569]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:33 volumio sudo[9571]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 11:30:33 volumio sudo[9571]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:33 volumio sudo[9573]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 08 11:30:33 volumio sudo[9573]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 08 11:30:33 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 08 11:30:33 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 08 11:30:33 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 08 11:30:33 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 08 11:30:33 volumio sudo[9573]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:33 volumio sudo[9571]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:33 volumio mpd_monitor.sh[9577]: MPD Monitor Service: Starting MPD Monitor Service Dec 08 11:30:33 volumio sudo[9569]: pam_unix(sudo:session): session closed for user root Dec 08 11:30:33 volumio volumio[9128]: info: Successfully started MPD Monitor Dec 08 11:30:33 volumio volumio[9128]: info: Successfully started MPD Monitor Dec 08 11:30:33 volumio volumio[9128]: info: Successfully started MPD Monitor Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-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 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-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 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-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 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-06:00" level=info msg="zeroconf server listening on port 40825" Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-06:00" level=debug msg="obtained new client token: AAA5oSb7CZcGQoN4wKe+C8q174eLm0U4/Erdp3Z7poKPA8EgSBKLhLGz3pWd4QAA2wmZWFRV4RH4f+HnIy7B5ZBovev+aN3OwP+ZUbC3IwXvWXmGP162+LTwhLzXTPVPGd6WPamrYAtKelF7xyml55gB+g9XrZDzor3jY964SPMDja2dtQ3RkZ9xuHtpmvXhQEoxZaojlCBSqqq1n9hQu664bypTmtGWznelG8ukCTPeqgSnXnQu0iM=" Dec 08 11:30:34 volumio volumio[9128]: info: Initializing connection to go-librespot Websocket Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-06:00" level=debug msg="new websocket client" Dec 08 11:30:34 volumio volumio[9128]: info: Connection to go-librespot Websocket established Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-06:00" level=warning msg="failed to connect to AP ap-guc3.spotify.com:4070, retrying with a different AP" error="dial tcp 104.154.127.247:4070: connect: connection refused" Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-06:00" level=debug msg="connected to ap-guc3.spotify.com:443" Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30:34-06:00" level=debug msg="completed challenge" Dec 08 11:30:34 volumio go-librespot[9562]: time="2025-12-08T11:30: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 08 11:30:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:34 volumio volumio[9128]: info: Connection to go-librespot Websocket closed Dec 08 11:30:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70. Dec 08 11:30:37 volumio systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:37 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 08 11:30:37 volumio go-librespot[9582]: go-librespot daemon starting... Dec 08 11:30:37 volumio go-librespot[9583]: time="2025-12-08T11:30:37-06:00" level=info msg="running go-librespot 0.4.0" Dec 08 11:30:37 volumio go-librespot[9583]: time="2025-12-08T11:30:37-06:00" level=debug msg="app state loaded" Dec 08 11:30:37 volumio go-librespot[9583]: time="2025-12-08T11:30:37-06:00" level=debug msg="stored credentials not found" Dec 08 11:30:37 volumio go-librespot[9583]: time="2025-12-08T11:30:37-06:00" level=info msg="api server listening on 127.0.0.1:9879" Dec 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-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 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-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 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-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 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-06:00" level=info msg="zeroconf server listening on port 46109" Dec 08 11:30:38 volumio volumio[9128]: info: Getting Spotify volume Dec 08 11:30:38 volumio volumio[9128]: info: Initializing connection to go-librespot Websocket Dec 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-06:00" level=debug msg="new websocket client" Dec 08 11:30:38 volumio volumio[9128]: 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 08 11:30:38 volumio volumio[9128]: info: Connection to go-librespot Websocket established Dec 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-06:00" level=debug msg="obtained new client token: AADbuGxOgriJkMPf5JsUoW0NQhQ7ItHWVhuAq3exf0LyliLC8v5F1MLb31Yn5/bXdZwwwVKBxQW/WqaRl2yvqglpXJYXurX6v8EWeBOr55SmsOFBcmzOjU2CXO6ngZ1ebkBh7dOyubexcEoB5gLJJVQdJFPe8lgL0AjxraccgPriZV8irKl62A4n0F5ddERmzqh/u3m7uSl3QuUVVmUdhJQw6QPS3+J0FxDh4RsX8FqkC5AUR+SwNGA=" Dec 08 11:30:38 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:38 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:38 volumio volumio[9128]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Dec 08 11:30:38 volumio volumio[9128]: SPOTIFY: SPOTIFY VOLUME undefined Dec 08 11:30:38 volumio volumio[9128]: SPOTIFY: VOLUMIO VOLUME 86 Dec 08 11:30:38 volumio volumio[9128]: info: Aligning Spotify Volume to Volumio Volume Dec 08 11:30:38 volumio volumio[9128]: info: CoreCommandRouter::volumioGetState Dec 08 11:30:38 volumio volumio[9128]: info: CorePlayQueue::getTrack 0 Dec 08 11:30:38 volumio volumio[9128]: info: Setting Spotify Volume from Volumio: 86 Dec 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-06:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Dec 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-06:00" level=debug msg="completed keyexchange" Dec 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30:38-06:00" level=debug msg="completed challenge" Dec 08 11:30:38 volumio go-librespot[9583]: time="2025-12-08T11:30: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 08 11:30:38 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 08 11:30:38 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 08 11:30:38 volumio volumio[9128]: info: Connection to go-librespot Websocket closed Dec 08 11:30:38 volumio volumio[9128]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 11:30:38 volumio volumio[9128]: Error: socket hang up Dec 08 11:30:38 volumio volumio[9128]: at connResetException (node:internal/errors:720:14) Dec 08 11:30:38 volumio volumio[9128]: at Socket.socketOnEnd (node:_http_client:519:23) Dec 08 11:30:38 volumio volumio[9128]: at Socket.emit (node:events:526:35) Dec 08 11:30:38 volumio volumio[9128]: at endReadableNT (node:internal/streams/readable:1376:12) Dec 08 11:30:38 volumio volumio[9128]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Dec 08 11:30:38 volumio volumio[9128]: code: 'ECONNRESET', Dec 08 11:30:38 volumio volumio[9128]: response: undefined Dec 08 11:30:38 volumio volumio[9128]: } Dec 08 11:30:38 volumio volumio[9128]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 08 11:30:39 volumio sudo[9604]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-08 11:29' Dec 08 11:30:39 volumio sudo[9604]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="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"