-- Logs begin at Wed 2025-04-16 14:52:24 +07, end at Wed 2025-04-16 15:09:56 +07. -- Apr 16 15:08:02 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:02 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 173. Apr 16 15:08:02 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:02 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:02 volumio go-librespot[7506]: Librespot-go daemon starting... Apr 16 15:08:02 volumio go-librespot[7506]: time="2025-04-16T15:08:02+07:00" level=info msg="generated new device id: 12610bdcf5daa62045d4c0ad0b322fecf7cefac8" Apr 16 15:08:02 volumio go-librespot[7506]: time="2025-04-16T15:08:02+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:02 volumio go-librespot[7506]: time="2025-04-16T15:08:02+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 16 15:08:02 volumio go-librespot[7506]: time="2025-04-16T15:08:02+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 16 15:08:02 volumio go-librespot[7506]: time="2025-04-16T15:08:02+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 16 15:08:02 volumio go-librespot[7506]: time="2025-04-16T15:08:02+07:00" level=debug msg="zeroconf server listening on port 32925" Apr 16 15:08:03 volumio go-librespot[7506]: time="2025-04-16T15:08:03+07:00" level=debug msg="obtained new client token: AAArKwBN2u2CJ9+ORGS8G5fyXnuoEuzDneNh2w2nozvuZl2hhBsF6Dcbr7wk5xKdDEueGGI35OXI8FkvGQpv1eW2ZmHb5Ffc0mhmUEeFDm/A/xM4E/Vz+W9+Ed+EDbi9yF8rt4hwJfPR8Ekg+rxakWPMnnNhNX8xRbBxJ99zmPawP+ob+bq1zo9isGnjrCzRozuU8V7VFlgBqjei95TcLT79u9wjdGgIw4C2mjKrkIL48RaLxwm2F9yN6A==" Apr 16 15:08:03 volumio go-librespot[7506]: time="2025-04-16T15:08:03+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:03 volumio go-librespot[7506]: time="2025-04-16T15:08:03+07:00" level=debug msg="completed challenge" Apr 16 15:08:03 volumio go-librespot[7506]: time="2025-04-16T15:08:03+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:05 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:05 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:06 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 16 15:08:06 volumio volumio[1080]: info: CURURI: albums:// Apr 16 15:08:06 volumio volumio[1080]: info: listAlbums - loading Albums from cache Apr 16 15:08:06 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 174. Apr 16 15:08:06 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:06 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:06 volumio go-librespot[7517]: Librespot-go daemon starting... Apr 16 15:08:06 volumio volumio[1080]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/*/f1933df0-606f-426b-8a0a-45821c989897.jpg' Apr 16 15:08:06 volumio go-librespot[7517]: time="2025-04-16T15:08:06+07:00" level=info msg="generated new device id: b1624d3cccd65eb720fe80f7852ce267d6144014" Apr 16 15:08:06 volumio go-librespot[7517]: time="2025-04-16T15:08:06+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=debug msg="zeroconf server listening on port 33403" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=debug msg="obtained new client token: AAC/8C1KBAf+1HWPB9PLA+OuV7v2m/Nlrt6yTWgR8j/Z/VeX32cLIL0RUN6kNkwHoU/0a+tGD3/2Nh3d0iKbv1Er4ihDLKVnpgCOVldFh5stqJ/3ceqKtCiyfRJKZM+y5KcRT4fWqiJORwExbudYuldwTY0VuPX4FcbCR67Ljl0yPLLgRT0LfJHk0XU9sxnaFum/EsFHfxjPl9aDMu1nRobsLPigvxvxPwYoVIumVc2uHR+HkKVygajpKg==" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=debug msg="completed challenge" Apr 16 15:08:07 volumio go-librespot[7517]: time="2025-04-16T15:08:07+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:08 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:08 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 175. Apr 16 15:08:10 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:10 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:10 volumio go-librespot[7527]: Librespot-go daemon starting... Apr 16 15:08:10 volumio go-librespot[7527]: time="2025-04-16T15:08:10+07:00" level=info msg="generated new device id: a72fc24e1c3eda9287661eff0de11abd45a21abe" Apr 16 15:08:10 volumio go-librespot[7527]: time="2025-04-16T15:08:10+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="zeroconf server listening on port 39817" Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="obtained new client token: AAA1aMUie3dhHInNYxkxZVmBXli4qH4Mr123K6UeA4pkoSxxOiz3tRG40yzzO1FJ0fbS8PBxOd37OKpG+ue10WpCaJMHfdo9bt9DaOsxMbd1UIlIOW6mpmSPdPSU+/WctSRMtCvzNDNE938urv3dxPaY2GPg8y7Tv5A2i3Nr2xaR8CVoesGackNfDyt4hqAWx7rQkRG6Z4KJ8/SP+dA011c2ALXEwU+BQdDAfHm9vO9VKDJgTFtHqHW4OQ==" Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:11 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="new websocket client" Apr 16 15:08:11 volumio volumio[1080]: info: Connection to go-librespot Websocket established Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=debug msg="completed challenge" Apr 16 15:08:11 volumio go-librespot[7527]: time="2025-04-16T15:08:11+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:11 volumio volumio[1080]: info: Connection to go-librespot Websocket closed Apr 16 15:08:14 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 16 15:08:14 volumio volumio[1080]: info: CURURI: albums://SOUND%20HD/Bolero%202%20-%20Cho%20t%3Fi%20v%3F%20ng%3Fy%20xua Apr 16 15:08:14 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav Apr 16 15:08:14 volumio volumio[1080]: info: Preloading song: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav' Apr 16 15:08:14 volumio volumio[1080]: info: No valid Plugin REST Endpoint Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Exploding uri music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav in service mpd Apr 16 15:08:14 volumio volumio[1080]: error: scanFolder - failure to stat '/mnt/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav' Apr 16 15:08:14 volumio volumio[1080]: info: Getting Spotify volume Apr 16 15:08:14 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:14 volumio volumio[1080]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Apr 16 15:08:14 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 24) Apr 16 15:08:14 volumio volumio[1080]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Apr 16 15:08:14 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:08:14 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:14 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:14 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:14 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 176. Apr 16 15:08:14 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:14 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:14 volumio go-librespot[7551]: Librespot-go daemon starting... Apr 16 15:08:14 volumio go-librespot[7551]: time="2025-04-16T15:08:14+07:00" level=info msg="generated new device id: 01eb1144f3453f7780f798ad7124f2ae57dde36a" Apr 16 15:08:14 volumio go-librespot[7551]: time="2025-04-16T15:08:14+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=debug msg="zeroconf server listening on port 44879" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=debug msg="obtained new client token: AACoI9tenMvCqB6VU+lFSQoVj7kYlJX30ldgI1rTLWn2I8sCoxT+5g0V/HxVnKmNqTxDRVCnh8tplrfG+WyrFECtz0+Qk7hnRYIcx6LMdjr+GI+8GLyKRnNkmagRhyQA4Xp77en8p6Tn6Y/RZbuVYesUbgusR+C1H2o+yAuje5UOpmk806LN/ixMfuQ40xyXv9oBnAfu9LO1jILrRmGSV3BAFl28zyE4hnNFDl28AbA6ZCnPOiItSc5PWw==" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=debug msg="completed challenge" Apr 16 15:08:15 volumio go-librespot[7551]: time="2025-04-16T15:08:15+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:16 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 15:08:16 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 15:08:16 volumio volumio[1080]: info: Discovery: Getting this device information Apr 16 15:08:16 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:08:16 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:16 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 15:08:17 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:17 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:18 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:18 volumio volumio[1080]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::ClearQueue Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::clearPlayQueue Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:18 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:08:18 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav Apr 16 15:08:18 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:08:18 volumio volumio[1080]: info: CoreCommandRouter::volumioPlay Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::play index 0 Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:08:18 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav Apr 16 15:08:18 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav Apr 16 15:08:18 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:18 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::play index undefined Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:18 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:08:18 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 177. Apr 16 15:08:18 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:18 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:18 volumio go-librespot[7559]: Librespot-go daemon starting... Apr 16 15:08:18 volumio go-librespot[7559]: time="2025-04-16T15:08:18+07:00" level=info msg="generated new device id: 0edb743227b6799ad77dc66ba1f86ef56dda4360" Apr 16 15:08:18 volumio go-librespot[7559]: time="2025-04-16T15:08:18+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:19 volumio go-librespot[7559]: time="2025-04-16T15:08:19+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:19 volumio go-librespot[7559]: time="2025-04-16T15:08:19+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:19 volumio go-librespot[7559]: time="2025-04-16T15:08:19+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:19 volumio go-librespot[7559]: time="2025-04-16T15:08:19+07:00" level=debug msg="zeroconf server listening on port 36735" Apr 16 15:08:19 volumio go-librespot[7559]: time="2025-04-16T15:08:19+07:00" level=debug msg="obtained new client token: AADzmjZweXTjAzbYqK6zjUcPgOAIZk8eIm9EtJlpt5ccel1dBgMj2RnEggLVYvvwzn+RXjN3ymOyXqRquqkBSJvX4EA6ZdkGAbSaP7jV65zL6sbXJgbUr3lGw1TAYQ0f9GWc2wC53/yfrLpYZVbu3VH+jJ9RUQzS4ZG6eAx0G1s2b1ZQK4CYIWzGufSX+HYF4Aarh6hru0zhgCSiCF1hwopuQtYOUGSjJ7J08wtXyJJmZebGiqMYIhrpXA==" Apr 16 15:08:19 volumio go-librespot[7559]: time="2025-04-16T15:08:19+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:20 volumio go-librespot[7559]: time="2025-04-16T15:08:20+07:00" level=debug msg="completed challenge" Apr 16 15:08:20 volumio go-librespot[7559]: time="2025-04-16T15:08:20+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:20 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:20 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:23 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:23 volumio volumio[1080]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::ClearQueue Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::clearPlayQueue Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:23 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:08:23 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav Apr 16 15:08:23 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:08:23 volumio volumio[1080]: info: CoreCommandRouter::volumioPlay Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::play index 1 Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:08:23 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav Apr 16 15:08:23 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav Apr 16 15:08:23 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:23 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::play index undefined Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:23 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:08:23 volumio volumio[1080]: info: CorePlayQueue::getTrack 1 Apr 16 15:08:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 178. Apr 16 15:08:23 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:23 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:23 volumio go-librespot[7581]: Librespot-go daemon starting... Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=info msg="generated new device id: eeb88a500ab260c762ff0af29cb41b4cae2a438f" Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=debug msg="zeroconf server listening on port 38115" Apr 16 15:08:23 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=debug msg="new websocket client" Apr 16 15:08:23 volumio volumio[1080]: info: Connection to go-librespot Websocket established Apr 16 15:08:23 volumio go-librespot[7581]: time="2025-04-16T15:08:23+07:00" level=debug msg="obtained new client token: AAA/ANCCMwie8SDu6zeqimvVw0Q2Igal6CbCeyGVTCCR69BBDUDlN9RHSVWe83dS6GC24KAEisntl36E0gtjfMdzSxarj9TCnVmZVvv+JZuXQOfhJUyhOLxS7ZCpncLtUZC1riUIdL2LiRQVqHa44aCE1IhEMByxO3/OCRg7R1RcijL3GUyHbRR4XDDjxdbStznzLUnOuESI9DabIT/muQ1VmRk06D9t58Srnunjd9SStH0VYGTu7TBkTg==" Apr 16 15:08:24 volumio go-librespot[7581]: time="2025-04-16T15:08:24+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:24 volumio go-librespot[7581]: time="2025-04-16T15:08:24+07:00" level=debug msg="completed challenge" Apr 16 15:08:24 volumio go-librespot[7581]: time="2025-04-16T15:08:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:24 volumio volumio[1080]: info: Connection to go-librespot Websocket closed Apr 16 15:08:25 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:25 volumio volumio[1080]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::ClearQueue Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::clearPlayQueue Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:25 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:08:25 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/01 Phi Nhung - Xin Tra Toi Ve.wav Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/02 Jang My - Ba Thang Ta Tu.wav Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/03 Qui Binh - Thoi Doi.wav Apr 16 15:08:25 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:08:25 volumio volumio[1080]: info: CoreCommandRouter::volumioPlay Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::play index 2 Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:08:25 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/04 Hoa Mi - Duong Xua Loi Cu.wav Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/05 To My - Ton Nu Con Buon.wav Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/06 Quang Linh - Hai Vi Sao Lac.wav Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/07 Trang My Dung - Nhat Ky Hai Dua Minh.wav Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/08 Ha Van - Nguoi Tinh Khong Den.wav Apr 16 15:08:25 volumio volumio[1080]: info: Adding Item to queue: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav Apr 16 15:08:25 volumio volumio[1080]: info: Using cached record of: music-library/USB/A_DUC/1.BOLERO TONG HOP/Bolero 2 - Cho tôi về ngày xưa/09 Ngoc Hoa - Gui Ve Anh.wav Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:25 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::play index undefined Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:25 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:08:25 volumio volumio[1080]: info: CorePlayQueue::getTrack 2 Apr 16 15:08:26 volumio volumio[1080]: info: Getting Spotify volume Apr 16 15:08:26 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:26 volumio volumio[1080]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Apr 16 15:08:26 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 25) Apr 16 15:08:26 volumio volumio[1080]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Apr 16 15:08:26 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:08:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:26 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:27 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:27 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 179. Apr 16 15:08:27 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:27 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:27 volumio go-librespot[7637]: Librespot-go daemon starting... Apr 16 15:08:27 volumio go-librespot[7637]: time="2025-04-16T15:08:27+07:00" level=info msg="generated new device id: 2b09e18fc19cd23e64a38a828f1722aa9dd0dea3" Apr 16 15:08:27 volumio go-librespot[7637]: time="2025-04-16T15:08:27+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:27 volumio go-librespot[7637]: time="2025-04-16T15:08:27+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:27 volumio go-librespot[7637]: time="2025-04-16T15:08:27+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:27 volumio go-librespot[7637]: time="2025-04-16T15:08:27+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:27 volumio go-librespot[7637]: time="2025-04-16T15:08:27+07:00" level=debug msg="zeroconf server listening on port 41043" Apr 16 15:08:27 volumio go-librespot[7637]: time="2025-04-16T15:08:27+07:00" level=debug msg="obtained new client token: AAAEhCV/U2YszAh0aw99ShV8Vr8vMZn5J7owpgGOfhB8806blCsaX2Q8dJL7FBCdouIhuPfQljgXr6xPWp7qzhrxFPsFV8KxgZk/SRczEg8qt0ga210/Wq1Vl9T40wdLnz4GDAfAoHv3yghmXG1u8GvqoYMHGjtBeKD6Xsh6y0keKyk1ylxgTzZtGZReGjW0urzjulXdxsNrrLRSSiRTw1SqnKvS2dOW/420McxZW7SxT2aMK6vkEiSbtw==" Apr 16 15:08:28 volumio go-librespot[7637]: time="2025-04-16T15:08:28+07:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.241.202:4070: connect: connection refused" Apr 16 15:08:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:30 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:30 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:31 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 180. Apr 16 15:08:31 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:31 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:31 volumio go-librespot[7647]: Librespot-go daemon starting... Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=info msg="generated new device id: 28923b1fe1acb7c29e002ea796c230c48e450d8d" Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=debug msg="zeroconf server listening on port 45439" Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=debug msg="obtained new client token: AAAH+bMBq5AeaUaxytTl1Y5vT1pRLUadfV7dIz+gDNDhrjCVk4oXpJWrdj2sdEgkYnnwsYZyUxsrj9I76k9OM8sC4BeRMue0yGEzbUDSmRlsnpiFacGq7tii1R5t7Egdo3S4Jiv9j5izT+1dI3sZglC1BaxB5hlHDCWtlxHb08QR1sV2em/HFXmSh71jAyFyBVccG/3AXEKr3zm8VlE1zWAhoQUOyWcnnt9qkasfEl3R9FNnLZjLn7k=" Apr 16 15:08:31 volumio go-librespot[7647]: time="2025-04-16T15:08:31+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:32 volumio go-librespot[7647]: time="2025-04-16T15:08:32+07:00" level=debug msg="completed challenge" Apr 16 15:08:32 volumio go-librespot[7647]: time="2025-04-16T15:08:32+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:32 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Apr 16 15:08:32 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:33 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:33 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 181. Apr 16 15:08:35 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:35 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:35 volumio go-librespot[7670]: Librespot-go daemon starting... Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=info msg="generated new device id: 205c7b6fbc605b0aff5f4c6db84f4cc56b79fa9b" Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=debug msg="zeroconf server listening on port 37349" Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=debug msg="obtained new client token: AAA58ArY87omb175rPuQQS4sBnX/5IHctshgAkrXtji6ZDAQq2lFREpJkDT139yg+hkaQs6+VUNXjdPTj0pE7ao62FeeKFLWT2KBFPYJ6RlHwF4ePrWSXlYwl4dfy/UjOFjfCeCw/YHypAuMU6/K+rZRB0ds1spj5HhTEL240eoJEqvwgF9z8rwk+AACf0y4hCj1caZaJ0l3oCc/xnTithB6xEnkZ3KzhkvA9F5m+f/SnDAykdvoEJA=" Apr 16 15:08:35 volumio go-librespot[7670]: time="2025-04-16T15:08:35+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:36 volumio go-librespot[7670]: time="2025-04-16T15:08:36+07:00" level=debug msg="completed challenge" Apr 16 15:08:36 volumio go-librespot[7670]: time="2025-04-16T15:08:36+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:36 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:36 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 182. Apr 16 15:08:39 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:39 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:39 volumio go-librespot[7678]: Librespot-go daemon starting... Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=info msg="generated new device id: 8e3b4e9764aa84f0305326552f955bd352bc79c8" Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="zeroconf server listening on port 41689" Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="obtained new client token: AABBAViThOA6U13nOcN3dQbIBzn5A7beD0U9z9UYkcr98vafbygc8LhgbD3hGmzEXDpo5evD7Dv76c5QvkyjL7HZimuybzE7ZfnQCfDm6GNDCEaypS8qGFicJIyd+LyL5n7NFMJTVN9Il9sT9iR/iLo4/2HnY2Pvo5OFAv/tMuImWWwtm4gKeoPmwLtHewhcRp2SMcmgW7rFtvvO2828+hanLsHxGXySBp6NQgg5NruYF0Rpd97Ksec=" Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:39 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:39 volumio go-librespot[7678]: time="2025-04-16T15:08:39+07:00" level=debug msg="new websocket client" Apr 16 15:08:39 volumio volumio[1080]: info: Connection to go-librespot Websocket established Apr 16 15:08:40 volumio go-librespot[7678]: time="2025-04-16T15:08:40+07:00" level=debug msg="completed challenge" Apr 16 15:08:40 volumio go-librespot[7678]: time="2025-04-16T15:08:40+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:40 volumio volumio[1080]: info: Connection to go-librespot Websocket closed Apr 16 15:08:41 volumio volumio[1080]: Searching plugin music_service/webradio Apr 16 15:08:41 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: webradio , search Apr 16 15:08:42 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Error: Start tag expected, '<' not found Apr 16 15:08:42 volumio volumio[1080]: at Object.module.exports.fromXml (/volumio/node_modules/libxmljs/lib/document.js:168:21) Apr 16 15:08:42 volumio volumio[1080]: at /volumio/app/plugins/music_service/webradio/index.js:949:31 Apr 16 15:08:42 volumio volumio[1080]: at runMicrotasks () Apr 16 15:08:42 volumio volumio[1080]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Apr 16 15:08:42 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 26) Apr 16 15:08:42 volumio volumio[1080]: Searching plugin music_service/webradio Apr 16 15:08:42 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: webradio , search Apr 16 15:08:42 volumio volumio[1080]: info: Getting Spotify volume Apr 16 15:08:42 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:42 volumio volumio[1080]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Apr 16 15:08:42 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 27) Apr 16 15:08:42 volumio volumio[1080]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Apr 16 15:08:42 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:08:42 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:42 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:43 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:43 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 183. Apr 16 15:08:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:43 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:43 volumio go-librespot[7704]: Librespot-go daemon starting... Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=info msg="generated new device id: fa889b89dba3229e46a16f20ab72b7db4f104703" Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=debug msg="zeroconf server listening on port 35847" Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=debug msg="obtained new client token: AAAm92BMuA8+zTCrR0z2mjiLkEWDZ3uJW69iaRTOTmCCPMvStjiwHJyJY6Xd843prsFlEZsZgRQc1NNeRrH5rhVwA9PXdVd4q/ydhTc8lMPSJ8CZ5OCWoSjgrHRncdwciM8nRSoX0Q84I9FvKDMlx9VoreN+bHnPPYdYMsr239Wh+he80hqbkfquCbEbTjJQXD+Hp9sNhCzePOAa+S7TeblaPb7wiBrWiiZ6DV7oDJHo50MmW9Bonqo=" Apr 16 15:08:43 volumio volumio[1080]: info: All search sources collected, pushing search results Apr 16 15:08:43 volumio go-librespot[7704]: time="2025-04-16T15:08:43+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:44 volumio go-librespot[7704]: time="2025-04-16T15:08:44+07:00" level=debug msg="completed challenge" Apr 16 15:08:44 volumio go-librespot[7704]: time="2025-04-16T15:08:44+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:46 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:46 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 15:08:46 volumio volumio[1080]: info: Discovery: Getting this device information Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 15:08:46 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::ClearQueue Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::clearPlayQueue Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:08:46 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:08:46 volumio volumio[1080]: info: Adding Item to queue: http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1770054 Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:08:46 volumio volumio[1080]: info: CoreCommandRouter::volumioPlay Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::play index 0 Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::play index undefined Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:46 volumio volumio[1080]: info: CoreStateMachine::startPlaybackTimer Apr 16 15:08:46 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:46 volumio volumio[1080]: info: [1744790926986] ControllerWebradio::clearAddPlayTrack Apr 16 15:08:46 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 15:08:46 volumio volumio[1080]: info: sendMpdCommand stop took 3 milliseconds Apr 16 15:08:46 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand clear Apr 16 15:08:46 volumio volumio[1080]: info: sendMpdCommand clear took 0 milliseconds Apr 16 15:08:46 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1770054" Apr 16 15:08:46 volumio volumio[1080]: info: Apr 16 15:08:46 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:46 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:46 volumio volumio[1080]: info: Apr 16 15:08:46 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:46 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:46 volumio volumio[1080]: info: Apr 16 15:08:46 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:46 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:46 volumio volumio[1080]: error: Upnp client error: Error: This socket has been ended by the other party Apr 16 15:08:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 184. Apr 16 15:08:47 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:47 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:47 volumio go-librespot[7716]: Librespot-go daemon starting... Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=info msg="generated new device id: 68cede0fc9a2e2370857e46b50b567764753ae2b" Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=debug msg="zeroconf server listening on port 39347" Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=debug msg="obtained new client token: AABPQaQwbTHJ9K4l2M/HQipJ7nL5+DI4xk5Zt1RMmBHm00Vh7DAPozNUKFGFXHWcZjBZ2FVJcjBrnDzNOjpsDQ3BqHvBCRMcqepBCpqfemG4Ug0GFIdhKUOwonAzxUrmBiqYqb9ohSG4eWVD+FJ2lXkn4uSw+WD0HqmocT3gQCSDD2kb4mvJwX4Y1UspB5bh+rjC72CQW9Oftquz8YFrx0DtpwZv8om1r2WqJ0JhzNQhtuwWOJr9jIc=" Apr 16 15:08:47 volumio go-librespot[7716]: time="2025-04-16T15:08:47+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:48 volumio go-librespot[7716]: time="2025-04-16T15:08:48+07:00" level=debug msg="completed challenge" Apr 16 15:08:48 volumio go-librespot[7716]: time="2025-04-16T15:08:48+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:48 volumio volumio[1080]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1770054" took 1687 milliseconds Apr 16 15:08:48 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 16 15:08:48 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand play Apr 16 15:08:48 volumio volumio[1080]: info: Apr 16 15:08:48 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:48 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:48 volumio volumio[1080]: info: ------------------------------ 1690ms Apr 16 15:08:48 volumio volumio[1080]: info: ------------------------------ 1689ms Apr 16 15:08:48 volumio volumio[1080]: info: ------------------------------ 1689ms Apr 16 15:08:48 volumio volumio[1080]: info: Apr 16 15:08:48 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:48 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:48 volumio volumio[1080]: info: Apr 16 15:08:48 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:48 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:48 volumio volumio[1080]: info: sendMpdCommand play took 8 milliseconds Apr 16 15:08:48 volumio volumio[1080]: info: ------------------------------ 13ms Apr 16 15:08:48 volumio volumio[1080]: info: ------------------------------ 10ms Apr 16 15:08:48 volumio volumio[1080]: info: ------------------------------ 9ms Apr 16 15:08:49 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:49 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:08:49 volumio volumio[1080]: info: FusionDsp - ---- read samplerate, raw: 384000,S32_LE,2,32 Apr 16 15:08:49 volumio volumio[1080]: info: FusionDsp - ---- read samplerate from file: 384000 Apr 16 15:08:49 volumio volumio[1080]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand status took 8 milliseconds Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:49 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand status took 11 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand status took 11 milliseconds Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:49 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:08:49 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:08:49 volumio volumio[1080]: info: Apr 16 15:08:49 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 7 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 7ms Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand status took 4 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 3ms Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 2ms Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"47 Kbps","isStreaming":false,"title":"113.164.229.226:8035","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8035","trackType":"226:8035"} Apr 16 15:08:49 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus stop Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":146,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"47 Kbps","isStreaming":false,"title":"113.164.229.226:8035","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8035","trackType":"226:8035"} Apr 16 15:08:49 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:08:49 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":167,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"47 Kbps","isStreaming":false,"title":"113.164.229.226:8035","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8035","trackType":"226:8035"} Apr 16 15:08:49 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:08:49 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 24ms Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 36ms Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 36ms Apr 16 15:08:49 volumio volumio[1080]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 20 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 20 milliseconds Apr 16 15:08:49 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 19 milliseconds Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:08:49 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":418,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"47 Kbps","isStreaming":false,"title":"113.164.229.226:8035","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8035","trackType":"226:8035"} Apr 16 15:08:49 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:08:49 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":418,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"47 Kbps","isStreaming":false,"title":"113.164.229.226:8035","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8035","trackType":"226:8035"} Apr 16 15:08:49 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:08:49 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":418,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"47 Kbps","isStreaming":false,"title":"113.164.229.226:8035","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8035","trackType":"226:8035"} Apr 16 15:08:49 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:08:49 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:08:49 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 63ms Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 59ms Apr 16 15:08:49 volumio volumio[1080]: info: ------------------------------ 60ms Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:49 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 185. Apr 16 15:08:51 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:51 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:51 volumio go-librespot[7740]: Librespot-go daemon starting... Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=info msg="generated new device id: 91cf7414852a81a1696e6db7408c340dcf8675f1" Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=debug msg="zeroconf server listening on port 36947" Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=debug msg="obtained new client token: AAAUOqZg17h8h6GLqcl7Jm2Nlken8RfxuV6z62k4SG042xR9+BtcXn91bN/ElMJAdRdNFkBK4UddZAQIKra4+6jySBK0x2s50ZROzoCAJmYkbRxp4H343FTpXA68HnsIH6jQJWNlTlV0FvyXjCKf8FEfUDDm1eqJZ+mhtZyFLl9zoS2+XyYjmLSqGbWCBL7tiL19jZfrY0zt2IM5T2vYd9aQoBf4p5dq5yEE4kFyQYsT2KG8I+5L+xk=" Apr 16 15:08:51 volumio go-librespot[7740]: time="2025-04-16T15:08:51+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:52 volumio go-librespot[7740]: time="2025-04-16T15:08:52+07:00" level=debug msg="completed challenge" Apr 16 15:08:52 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:52 volumio go-librespot[7740]: time="2025-04-16T15:08:52+07:00" level=debug msg="new websocket client" Apr 16 15:08:52 volumio volumio[1080]: info: Connection to go-librespot Websocket established Apr 16 15:08:52 volumio go-librespot[7740]: time="2025-04-16T15:08:52+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:52 volumio volumio[1080]: info: Connection to go-librespot Websocket closed Apr 16 15:08:55 volumio volumio[1080]: info: Getting Spotify volume Apr 16 15:08:55 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:55 volumio volumio[1080]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Apr 16 15:08:55 volumio volumio[1080]: (node:1080) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 28) Apr 16 15:08:55 volumio volumio[1080]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Apr 16 15:08:55 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:55 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:55 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:08:55 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:08:55 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 186. Apr 16 15:08:55 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:55 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:55 volumio go-librespot[7770]: Librespot-go daemon starting... Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=info msg="generated new device id: 7744db2ee5e92575ef3d90a7e593c1f78e61a9e1" Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=debug msg="zeroconf server listening on port 39005" Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=debug msg="obtained new client token: AABl0+y3yokQ4bq9K7hzltKC7RRz13lI3WTSarnawp9oJYPJVbom58ow+IeqLUBsaez2lvw8/c5qTZMWLUI/LRSi1QNIaA/9GSQf184UC+MruodoxmJ539pRTzJbbNqomd68q0sdD/1OJ0uHCBvkDP1yP/XaWcbyuIW4usQzXvwLuEbQJ3Dog/Qa638B78rm+XqEIEXsRwvYwn9L00SDTqK6mHWMtRIYI14ZTz5c7yb8DEqUNes0wUU=" Apr 16 15:08:55 volumio go-librespot[7770]: time="2025-04-16T15:08:55+07:00" level=debug msg="completed keyexchange" Apr 16 15:08:56 volumio go-librespot[7770]: time="2025-04-16T15:08:56+07:00" level=debug msg="completed challenge" Apr 16 15:08:56 volumio go-librespot[7770]: time="2025-04-16T15:08:56+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:08:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:08:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:08:58 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:08:58 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:08:59 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:08:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 187. Apr 16 15:08:59 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:08:59 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:08:59 volumio go-librespot[7787]: Librespot-go daemon starting... Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=info msg="generated new device id: 9123f2f3cd741122017b821f31ef4080a8146a16" Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=debug msg="zeroconf server listening on port 34567" Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=debug msg="obtained new client token: AACXgjLrtsvczQo1t7jfE4AIgloybWfbYM96KVtex0yLStdFJJzzkBzhNTvuIH73fpXZNwItbBkdIfaJhDkAk/rUBoJEUKGsvpLIOUF8EFeInCVTsbBQnpdFn8HziX7oh14ZCYkfgdy5tXh/Ql8EoqO9Ko4gkixmiYXqzxUyThncz4v0O2z1qP43R3a6uNrmTYz8Q2LwlB/r4G+Rm+/LqJDZXnX0m2bicdD2pMFBVKoHhJBnbJsJUw8=" Apr 16 15:08:59 volumio go-librespot[7787]: time="2025-04-16T15:08:59+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:00 volumio go-librespot[7787]: time="2025-04-16T15:09:00+07:00" level=debug msg="completed challenge" Apr 16 15:09:00 volumio go-librespot[7787]: time="2025-04-16T15:09:00+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:00 volumio ntpd[1586]: Soliciting pool server 2400:6760:0:200::254 Apr 16 15:09:00 volumio ntpd[1586]: Soliciting pool server 103.184.124.254 Apr 16 15:09:00 volumio ntpd[1586]: Soliciting pool server 115.165.161.155 Apr 16 15:09:01 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:01 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:01 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::ClearQueue Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::stPlaybackTimer Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::serviceStop Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::serviceStop Apr 16 15:09:01 volumio volumio[1080]: info: [1744790941460] ControllerWebradio::stop Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::clearPlayQueue Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:09:01 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:01 volumio volumio[1080]: info: Adding Item to queue: http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1775687 Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::volumioPlay Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::play index 0 Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::play index undefined Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::startPlaybackTimer Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: [1744790941475] ControllerWebradio::clearAddPlayTrack Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 15:09:01 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand stop took 15 milliseconds Apr 16 15:09:01 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand stop took 2 milliseconds Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand clear Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:01 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:01 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:01 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand clear took 2 milliseconds Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand status took 1 milliseconds Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1775687" Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:01 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Apr 16 15:09:01 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:01 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:01 volumio volumio[1080]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 16ms Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 15ms Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:01 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:01 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:01 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:01 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:01 volumio volumio[1080]: error: updateQueue error: null Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:01 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 246ms Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 246 milliseconds Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1775687" took 245 milliseconds Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:01 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 16 15:09:01 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand play Apr 16 15:09:01 volumio volumio[1080]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 251ms Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 234ms Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 233ms Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 4ms Apr 16 15:09:01 volumio volumio[1080]: info: sendMpdCommand play took 2 milliseconds Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:01 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:01 volumio volumio[1080]: info: Apr 16 15:09:01 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:01 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 1ms Apr 16 15:09:01 volumio volumio[1080]: info: ------------------------------ 0ms Apr 16 15:09:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 188. Apr 16 15:09:03 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:03 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:03 volumio go-librespot[7827]: Librespot-go daemon starting... Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=info msg="generated new device id: 6d0e9546ac0c1be9892b91582fc5ee501152b667" Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=debug msg="zeroconf server listening on port 38797" Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - ---- read samplerate, raw: 384000,S32_LE,2,32 Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - ---- read samplerate from file: 384000 Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - ---- read samplerate, raw: 384000,S32_LE,2,32 Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - ---- read samplerate from file: 384000 Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:03 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand status took 26 milliseconds Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand status took 25 milliseconds Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:03 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:03 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:03 volumio volumio[1080]: info: Apr 16 15:09:03 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 4ms Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand status took 4 milliseconds Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 3 milliseconds Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 3ms Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 3ms Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand status took 3 milliseconds Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"113.164.229.226:7043","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7043","trackType":"226:7043"} Apr 16 15:09:03 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus stop Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"51 Kbps","isStreaming":false,"title":"113.164.229.226:7043","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7043","trackType":"226:7043"} Apr 16 15:09:03 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:03 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"51 Kbps","isStreaming":false,"title":"113.164.229.226:7043","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7043","trackType":"226:7043"} Apr 16 15:09:03 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:03 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 46ms Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 60ms Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 59ms Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 30 milliseconds Apr 16 15:09:03 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 24 milliseconds Apr 16 15:09:03 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":460,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"51 Kbps","isStreaming":false,"title":"113.164.229.226:7043","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7043","trackType":"226:7043"} Apr 16 15:09:03 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:03 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":460,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"51 Kbps","isStreaming":false,"title":"113.164.229.226:7043","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7043","trackType":"226:7043"} Apr 16 15:09:03 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:03 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":460,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"51 Kbps","isStreaming":false,"title":"113.164.229.226:7043","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7043","trackType":"226:7043"} Apr 16 15:09:03 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:03 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:03 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=debug msg="obtained new client token: AABSNl1F5Pa3/sfshNsFmczYYBS6H9d63Ar647o8Nea4zr6oxN5ozG6gplGFw13JouJVVavZKKiEvlLWVQBbG4o5XG9IVnL6WHoHT1Q6yt4NK3erv4NPWbWJvSVBVZxaFZzCf1RsPivoctv6PH/qKrwwSODetE18yFAhKAKnFGxMbGe2ywfDf3qcmM1+qFNiy03dYqvgXQjOgpzwEt5C8SmMMB/hJGcLAOzPnlF8cz+UEW60qELekOM=" Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 84ms Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 82ms Apr 16 15:09:03 volumio volumio[1080]: info: ------------------------------ 82ms Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:03 volumio volumio[1080]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 16 15:09:03 volumio go-librespot[7827]: time="2025-04-16T15:09:03+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:04 volumio go-librespot[7827]: time="2025-04-16T15:09:04+07:00" level=debug msg="completed challenge" Apr 16 15:09:04 volumio go-librespot[7827]: time="2025-04-16T15:09:04+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:04 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:04 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:06 volumio ntpd[1586]: Soliciting pool server 103.199.19.135 Apr 16 15:09:07 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:07 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:07 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 189. Apr 16 15:09:07 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:07 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:07 volumio go-librespot[7852]: Librespot-go daemon starting... Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=info msg="generated new device id: 990b638c85f9b2c1ce280f8c3df4e275a098d10d" Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=debug msg="zeroconf server listening on port 43281" Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=debug msg="obtained new client token: AAB3zhBONtr02k1t0oqmwFt/ipUWDGv52Oyx3m/wZqpZqf1xTd0cr8nS6yaLL9gniMsNgn3gml0B8y8WyrgVHgiYnjFGrduOq60o9vagvFiwMlzb25jQe0jygxE5f9Uw9JTk/kPLHH35dYy30ec6XsN25gEl1jy9sFlW4mfSkPtXFkf6u+YTeBOCx7nGF6izxCTt2hlB/UKaeEXwSUcK4z5uKzo6T9pSEeYpt9S7Gyrc2VxM3seJorI=" Apr 16 15:09:07 volumio go-librespot[7852]: time="2025-04-16T15:09:07+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:07 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::ClearQueue Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::stPlaybackTimer Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::serviceStop Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::serviceStop Apr 16 15:09:07 volumio volumio[1080]: info: [1744790947917] ControllerWebradio::stop Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::clearPlayQueue Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:09:07 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:07 volumio volumio[1080]: info: Adding Item to queue: http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1643605 Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::volumioPlay Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::play index 0 Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::play index undefined Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::startPlaybackTimer Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: [1744790947931] ControllerWebradio::clearAddPlayTrack Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 15:09:07 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:07 volumio volumio[1080]: info: Apr 16 15:09:07 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:07 volumio volumio[1080]: info: sendMpdCommand stop took 17 milliseconds Apr 16 15:09:07 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:07 volumio volumio[1080]: info: sendMpdCommand stop took 3 milliseconds Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand clear Apr 16 15:09:07 volumio volumio[1080]: info: Apr 16 15:09:07 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:07 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:07 volumio volumio[1080]: info: Apr 16 15:09:07 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:07 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:07 volumio volumio[1080]: info: Apr 16 15:09:07 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:07 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:07 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:07 volumio volumio[1080]: info: sendMpdCommand clear took 2 milliseconds Apr 16 15:09:07 volumio volumio[1080]: info: sendMpdCommand status took 1 milliseconds Apr 16 15:09:07 volumio volumio[1080]: info: sendMpdCommand status took 0 milliseconds Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1643605" Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:07 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Apr 16 15:09:07 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:07 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:07 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:07 volumio volumio[1080]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Apr 16 15:09:07 volumio volumio[1080]: info: ------------------------------ 15ms Apr 16 15:09:07 volumio volumio[1080]: info: ------------------------------ 15ms Apr 16 15:09:07 volumio volumio[1080]: info: Apr 16 15:09:07 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:07 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:07 volumio volumio[1080]: info: Apr 16 15:09:07 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:07 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:07 volumio volumio[1080]: error: updateQueue error: null Apr 16 15:09:07 volumio volumio[1080]: info: ------------------------------ 15ms Apr 16 15:09:07 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 14 milliseconds Apr 16 15:09:07 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:07 volumio volumio[1080]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 16 15:09:07 volumio volumio[1080]: info: ------------------------------ 19ms Apr 16 15:09:07 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:07 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:08 volumio go-librespot[7852]: time="2025-04-16T15:09:08+07:00" level=debug msg="completed challenge" Apr 16 15:09:08 volumio go-librespot[7852]: time="2025-04-16T15:09:08+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:08 volumio volumio[1080]: info: Apr 16 15:09:08 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:08 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:08 volumio volumio[1080]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1643605" took 238 milliseconds Apr 16 15:09:08 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 16 15:09:08 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand play Apr 16 15:09:08 volumio volumio[1080]: info: ------------------------------ 226ms Apr 16 15:09:08 volumio volumio[1080]: info: ------------------------------ 226ms Apr 16 15:09:08 volumio volumio[1080]: info: ------------------------------ 2ms Apr 16 15:09:08 volumio volumio[1080]: info: Apr 16 15:09:08 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:08 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:08 volumio volumio[1080]: info: Apr 16 15:09:08 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:08 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:08 volumio volumio[1080]: info: sendMpdCommand play took 2 milliseconds Apr 16 15:09:08 volumio volumio[1080]: info: ------------------------------ 1ms Apr 16 15:09:08 volumio volumio[1080]: info: ------------------------------ 1ms Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - ---- read samplerate, raw: 384000,S32_LE,2,32 Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - ---- read samplerate from file: 384000 Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - ---- read samplerate, raw: 384000,S32_LE,2,32 Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - ---- read samplerate from file: 384000 Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 17 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 18 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 17 milliseconds Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 2 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 1 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 1 milliseconds Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"113.164.229.226:8005","artist":"(#1 - 15/512) VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus stop Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"113.164.229.226:8005","artist":"(#1 - 15/512) VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"113.164.229.226:8005","artist":"(#1 - 15/512) VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 30ms Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 45ms Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 44ms Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 25 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 25 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 25 milliseconds Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"113.164.229.226:8005","artist":"(#1 - 15/512) VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"113.164.229.226:8005","artist":"(#1 - 15/512) VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"113.164.229.226:8005","artist":"(#1 - 15/512) VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 58ms Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 56ms Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 56ms Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 16 15:09:09 volumio volumio[1080]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:09 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:09 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:09 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:09 volumio volumio[1080]: info: Apr 16 15:09:09 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 2ms Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 2ms Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 2ms Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand status took 1 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 1 milliseconds Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":167,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"160 Kbps","isStreaming":false,"title":"113.164.229.226:8005","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 14ms Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 11 milliseconds Apr 16 15:09:09 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 11 milliseconds Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":355,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"160 Kbps","isStreaming":false,"title":"113.164.229.226:8005","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":376,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":1,"random":false,"updatedb":false,"repeat":false,"bitrate":"160 Kbps","isStreaming":false,"title":"113.164.229.226:8005","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:8005","trackType":"226:8005"} Apr 16 15:09:09 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:09 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:09 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 28ms Apr 16 15:09:09 volumio volumio[1080]: info: ------------------------------ 28ms Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:09 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:10 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:10 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 190. Apr 16 15:09:11 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:11 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:11 volumio go-librespot[7886]: Librespot-go daemon starting... Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=info msg="generated new device id: 28122acd5f067c40ed9248b2f1f911f504a42827" Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=debug msg="zeroconf server listening on port 45505" Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=debug msg="obtained new client token: AACL0QB8xBgdpBbSLAMnGN6C5sD/FCNPvX9OAceeutgk0KQV3gWhIOuZ69XpDsewX1At0a6CghDxmso+U2XYyhCNHCrDMD2xtVrkoZTiBfA3us6PZ8BvlqzVjmMe+iEHP9hbk4YwR1XRkq9riK8VmXkXo5ld9Osw4G59QpbAscq9vjANkJouTI5FA7HpVvaQiW0MWjm3cpq072QtKxi5swS9/LxPmscW50FAQc0QwLT/OA6AfydYK4E=" Apr 16 15:09:11 volumio go-librespot[7886]: time="2025-04-16T15:09:11+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:12 volumio go-librespot[7886]: time="2025-04-16T15:09:12+07:00" level=debug msg="completed challenge" Apr 16 15:09:12 volumio go-librespot[7886]: time="2025-04-16T15:09:12+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:13 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:13 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 191. Apr 16 15:09:15 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:15 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:15 volumio go-librespot[7916]: Librespot-go daemon starting... Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=info msg="generated new device id: 8ac9cfad9cc4c3a9943551b520803ffe84313432" Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=debug msg="zeroconf server listening on port 35835" Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=debug msg="obtained new client token: AACEhMvXFvxmmy48zuvCNYzKHjizL6V02wzQqauedF+bSC+NvgUWmAAu/xWxBrugPe1VRtj30BegbNLtfzEyvw1ZXMW6qkdBIGORSYdcSP1ZDP1FUMXfSR/Vb9O9sksPa+O+d4eRbaEd8RR3LRyHgO6Fz2ofmyiEdcj8wctiY9t4buYZNt2ZmaQ7hc+8/xXLbzFiouoX3gMBGDBygLD2a8bTjo6JJAAoc3NeF3oVFWLQrZAUgkiIy6I=" Apr 16 15:09:15 volumio go-librespot[7916]: time="2025-04-16T15:09:15+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:16 volumio go-librespot[7916]: time="2025-04-16T15:09:16+07:00" level=debug msg="completed challenge" Apr 16 15:09:16 volumio go-librespot[7916]: time="2025-04-16T15:09:16+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:16 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:16 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:16 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 15:09:16 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 15:09:16 volumio volumio[1080]: info: Discovery: Getting this device information Apr 16 15:09:16 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:09:16 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 15:09:19 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:19 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 192. Apr 16 15:09:19 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:19 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:19 volumio go-librespot[7933]: Librespot-go daemon starting... Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=info msg="generated new device id: 1700d8ea5641f0a644a925c9e88bfb874648f7e0" Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=debug msg="zeroconf server listening on port 34571" Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=debug msg="obtained new client token: AABsTeD7WncZXXmoXTuV3iEcWE0DynuQezX+ciBlrHfoixFqEXKD65ad9YsU/ZyWD94gxJEbwQnVhN8kDC/T0xjrqOPCZZ9yD1zH22Gf8EhVhiU0rP41cl+p+CBtlRbExAnP2rIxHD0k96ghnyil+UHGuL88UkKIgDPVY1TkCYvkRGyX0/v1DMXFHH/hNWIJfksqyItVPEvUggUBpilE5Uhcck0VwSq5bXli+bl/AfV0vp8Wwm1yfwA=" Apr 16 15:09:19 volumio go-librespot[7933]: time="2025-04-16T15:09:19+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:20 volumio go-librespot[7933]: time="2025-04-16T15:09:20+07:00" level=debug msg="completed challenge" Apr 16 15:09:20 volumio go-librespot[7933]: time="2025-04-16T15:09:20+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:22 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:22 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 193. Apr 16 15:09:23 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:23 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:23 volumio go-librespot[7965]: Librespot-go daemon starting... Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=info msg="generated new device id: 19a46839ad5bebff4b7d6d179be291a2b4a1a13e" Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=debug msg="zeroconf server listening on port 34615" Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=debug msg="obtained new client token: AAA8gBbOAXf9IHH70/VsafPEKeyR6jI1HgTazKA/alv3Echy3fDSKO0RfFowUl8kg5XqF1FBT0nHUocWBruvyomp3oM2x3CGmFsqILcSLJHeKw6OjM1xFCjyBb4eJKiJuDErhe8ccvpYjdGJfEhlvfV4RkNLZWA+IdipbNRbDMEY3L8aAfXz7HOrJbqoMRQuxOQrzHo1uDra71nQkhDNIiSJZBWZAXwo5lj7Dj4UjbPgrPvQxrt5KKc=" Apr 16 15:09:23 volumio go-librespot[7965]: time="2025-04-16T15:09:23+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:24 volumio go-librespot[7965]: time="2025-04-16T15:09:24+07:00" level=debug msg="completed challenge" Apr 16 15:09:24 volumio go-librespot[7965]: time="2025-04-16T15:09:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:25 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:25 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:26 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::ClearQueue Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::stPlaybackTimer Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::serviceStop Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::serviceStop Apr 16 15:09:26 volumio volumio[1080]: info: [1744790966722] ControllerWebradio::stop Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::clearPlayQueue Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::addQueueItems Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::addQueueItems Apr 16 15:09:26 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:26 volumio volumio[1080]: info: Adding Item to queue: http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1910289 Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::volumioPushQueue Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::saveQueue Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::updateTrackBlock Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrackBlock Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::volumioPlay Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::play index 0 Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::stop Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::play index undefined Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::startPlaybackTimer Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: [1744790966730] ControllerWebradio::clearAddPlayTrack Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 15:09:26 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand stop took 9 milliseconds Apr 16 15:09:26 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand stop took 2 milliseconds Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand clear Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:26 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:26 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:26 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand clear took 2 milliseconds Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand status took 1 milliseconds Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1910289" Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:26 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 11ms Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:26 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand status took 10 milliseconds Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:26 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:26 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:26 volumio volumio[1080]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received mpd Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 16ms Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:26 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:26 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:26 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:26 volumio volumio[1080]: error: updateQueue error: null Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:26 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 238ms Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 237 milliseconds Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=1910289" took 237 milliseconds Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:26 volumio volumio[1080]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 16 15:09:26 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand play Apr 16 15:09:26 volumio volumio[1080]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 241ms Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 231ms Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 224ms Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 3ms Apr 16 15:09:26 volumio volumio[1080]: info: sendMpdCommand play took 3 milliseconds Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:26 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:26 volumio volumio[1080]: info: Apr 16 15:09:26 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:26 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 1ms Apr 16 15:09:26 volumio volumio[1080]: info: ------------------------------ 1ms Apr 16 15:09:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 194. Apr 16 15:09:27 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:27 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:27 volumio go-librespot[8038]: Librespot-go daemon starting... Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=info msg="generated new device id: 927a26fd85bffef962270eebe7e219c425abffd4" Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=debug msg="zeroconf server listening on port 46347" Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=debug msg="obtained new client token: AAD4Y7g5tyhgRUEVUnrt6suV5TAwcU3V6R3ojjOA8l5GfDlPKjqPtdbeIWiAl6w+NOZeYKueB3sEsoo5zGFLi0CRLvek42FtCocTQlAnCe9EV5jmwNlD8NJbZsZK3TYDa8xHZ4nJdJpxiWtPsMrZw8LUdlS0JGRp0rzrNhay+5lWGgRA5FBoYj5rnyO4cZ3aZruw16WDDkCK5S65jXpjCPaSGbZ7RJ69kbSHkfSIXJ7NTF6/cW7XlKk=" Apr 16 15:09:27 volumio go-librespot[8038]: time="2025-04-16T15:09:27+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:28 volumio go-librespot[8038]: time="2025-04-16T15:09:28+07:00" level=debug msg="completed challenge" Apr 16 15:09:28 volumio go-librespot[8038]: time="2025-04-16T15:09:28+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:28 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:28 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:28 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:28 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - ---- read samplerate, raw: 384000,S32_LE,2,32 Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - ---- read samplerate from file: 384000 Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - ---- read samplerate, raw: 384000,S32_LE,2,32 Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - ---- read samplerate from file: 384000 Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - If filter freq >samplerate/2 then disable it Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:28 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand status took 27 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand status took 26 milliseconds Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:28 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces system playlist update Apr 16 15:09:28 volumio volumio[1080]: info: Ignoring MPD Status Update Apr 16 15:09:28 volumio volumio[1080]: info: Apr 16 15:09:28 volumio volumio[1080]: ---------------------------- MPD announces state update: player Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::getState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand status Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 5ms Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand status took 5 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 4ms Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand status took 4 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 4ms Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand status took 2 milliseconds Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseState Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"130 Kbps","isStreaming":false,"title":"113.164.229.226:7045","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7045","trackType":"226:7045"} Apr 16 15:09:28 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus stop Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"130 Kbps","isStreaming":false,"title":"113.164.229.226:7045","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7045","trackType":"226:7045"} Apr 16 15:09:28 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:28 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"130 Kbps","isStreaming":false,"title":"113.164.229.226:7045","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7045","trackType":"226:7045"} Apr 16 15:09:28 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:28 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 45ms Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 58ms Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 59ms Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 28 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 28 milliseconds Apr 16 15:09:28 volumio volumio[1080]: info: sendMpdCommand playlistinfo took 28 milliseconds Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:28 volumio volumio[1080]: verbose: ControllerMpd::parseTrackInfo Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":418,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"130 Kbps","isStreaming":false,"title":"113.164.229.226:7045","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7045","trackType":"226:7045"} Apr 16 15:09:28 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:28 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":428,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"130 Kbps","isStreaming":false,"title":"113.164.229.226:7045","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7045","trackType":"226:7045"} Apr 16 15:09:28 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:28 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: ControllerMpd::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::servicePushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: verbose: STATE SERVICE {"status":"play","position":0,"seek":428,"duration":0,"samplerate":48,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"130 Kbps","isStreaming":false,"title":"113.164.229.226:7045","artist":"VOV1_TNVN1","album":null,"uri":"http://113.164.229.226:7045","trackType":"226:7045"} Apr 16 15:09:28 volumio volumio[1080]: verbose: CURRENT POSITION 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState stateService play Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::syncState currentStatus play Apr 16 15:09:28 volumio volumio[1080]: info: Received an update from plugin. extracting info from payload Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CorePlayQueue::getTrack 0 Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreStateMachine::pushState Apr 16 15:09:28 volumio volumio[1080]: info: CoreCommandRouter::volumioPushState Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 70ms Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 69ms Apr 16 15:09:28 volumio volumio[1080]: info: ------------------------------ 68ms Apr 16 15:09:28 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:28 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:28 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:28 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:28 volumio volumio[1080]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 16 15:09:28 volumio volumio[1080]: info: FusionDsp - {"Reload":{"result":"Ok"}} Apr 16 15:09:31 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:31 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:31 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:31 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 195. Apr 16 15:09:31 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:31 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:31 volumio go-librespot[8063]: Librespot-go daemon starting... Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=info msg="generated new device id: 1c5af1101db2531a916d4e335c1877310bcaace9" Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=debug msg="zeroconf server listening on port 37727" Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=debug msg="obtained new client token: AACQIG9rMtxf1ZwnVKllybwQOegCWy8xPHAOpmsvPAsOuaedzbcaZWufIIMLgkWiLhCCGzIVaPbI9I9GqlBy3Kd3Rj4AULQVrZyfFD1Edxe4gyxYhSmiGFmm3zTDOymzOa9wEMdg/LP67G/cFx35NXNysKyPrzbiRd+9DEkv6nGtPnb5ims5G0U/iFPXAtNn5w1Sp5CnVBvYt1PimEcEochTJ3gU7JqsAd6xCX4CL1nVglmMvmEUkhc=" Apr 16 15:09:31 volumio go-librespot[8063]: time="2025-04-16T15:09:31+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:32 volumio go-librespot[8063]: time="2025-04-16T15:09:32+07:00" level=debug msg="completed challenge" Apr 16 15:09:32 volumio go-librespot[8063]: time="2025-04-16T15:09:32+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:34 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:34 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 196. Apr 16 15:09:35 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:35 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:35 volumio go-librespot[8093]: Librespot-go daemon starting... Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=info msg="generated new device id: 2eee2521e76783b6f6e52cf65bb4ef3901d1481a" Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=debug msg="zeroconf server listening on port 39489" Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=debug msg="obtained new client token: AAAfR8kYho9uLIIPTa16h5N0K2+lPY6jmspRc/F+vggXCnkJMvMKh3AgJoJ1YTZ+BQ3R7ZdAqAJhA6vIzB5jUSb/0AbObPjfO1vku+PZ64ESr+gXgndO7jaVuAHl/joiS9v4nyhfdPhLJiT5bsXq3wrAwcCpaHirLqvQ7k7yL092ETW7AxybWuPZck2R7sQM4AkzgZ9AFTIW8LiX7V18wdb3sVUyKNzZf/jB20SMCxsKMwKePrzVhT4=" Apr 16 15:09:35 volumio go-librespot[8093]: time="2025-04-16T15:09:35+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:36 volumio go-librespot[8093]: time="2025-04-16T15:09:36+07:00" level=debug msg="completed challenge" Apr 16 15:09:36 volumio go-librespot[8093]: time="2025-04-16T15:09:36+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:37 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:37 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 197. Apr 16 15:09:39 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:39 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:39 volumio go-librespot[8109]: Librespot-go daemon starting... Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=info msg="generated new device id: e17dff00fe626a1d56de9e92cff7ad8ca9d559aa" Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=debug msg="zeroconf server listening on port 40121" Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=debug msg="obtained new client token: AADfm+I3WXnye/bc8KU6i65niV2CI9z8t78gHjsI900ne+NKwc3NYqnQsJzB6/H2tJ6ZNMjF0jB+PLjxroRzta1F35Snjt0ZqTlMyQ8IUGTWvEzlT5mQJi+G+Z4OJw4ugMFzK08Dl1FHhTwidvYy6e350PX5WHCF/vNmn38yHKfiTD88N9/ZnJMbJa57VBTlWYd+kE8q7dLn0czfLbrMTH6qJ14d1nGs2Fk7nt/CE7GxCzHXHpGYZaM=" Apr 16 15:09:39 volumio go-librespot[8109]: time="2025-04-16T15:09:39+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:40 volumio go-librespot[8109]: time="2025-04-16T15:09:40+07:00" level=debug msg="completed challenge" Apr 16 15:09:40 volumio go-librespot[8109]: time="2025-04-16T15:09:40+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:40 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:40 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:43 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:43 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 198. Apr 16 15:09:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:43 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:43 volumio go-librespot[8140]: Librespot-go daemon starting... Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=info msg="generated new device id: d6a5b92f04b21b44fa3128c71bcda4d2565bab04" Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=debug msg="zeroconf server listening on port 43751" Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=debug msg="obtained new client token: AADoEYoEHqGgl1pmdlG1rTaes9bJXra2lOEobcjH/XLO5jRJmzp+1pdq54WyBx0rRSlGspCd/7E72ZJzdzg55RHQMtUOa2spkFL+jNc/f2MabVeEZ0wODJ+mxtIm4cEIIjg3AksIi/XCZKfcZw9H9fl4E87DsUmS1TtjIs2tTebPyb+Od2O9Y5qIkNFLDG9zwlA6mlhnkChrNLJMeVI1ojaAMoYnCGA57qpXwkU/wJWIsHeaJOre2Yo=" Apr 16 15:09:43 volumio go-librespot[8140]: time="2025-04-16T15:09:43+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:44 volumio go-librespot[8140]: time="2025-04-16T15:09:44+07:00" level=debug msg="completed challenge" Apr 16 15:09:44 volumio go-librespot[8140]: time="2025-04-16T15:09:44+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:46 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:46 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:46 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 15:09:46 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 15:09:46 volumio volumio[1080]: info: Discovery: Getting this device information Apr 16 15:09:46 volumio volumio[1080]: info: CoreCommandRouter::volumioGetState Apr 16 15:09:46 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 15:09:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 199. Apr 16 15:09:47 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:47 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:47 volumio go-librespot[8159]: Librespot-go daemon starting... Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=info msg="generated new device id: 7fd0339260c978c2776e982e5cd9550fe85a3b31" Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=debug msg="zeroconf server listening on port 38071" Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=debug msg="obtained new client token: AADfYmqp/Mi0zfnUprCEHqUzKHHyw8uBAjxt4NNN1HEPWVcsBrXruc5JB1f2iGL8GsLzrHGj+bHqLU4ylv30vAAnmRro6y1/V/xfD0xS9rRGYUJfFzKK8mWb4rpe0WW9m9D311wD08u2xwJ0YBombzKATi0SFnh5Iqz2PsA0HjI2AVjp8KEssYrbSUoMckLr6NETeHdg/QRKxtgefkH6KZ8IrRp9MQqXKHeu4rXxPWHw83++aj/A0TY=" Apr 16 15:09:47 volumio go-librespot[8159]: time="2025-04-16T15:09:47+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:48 volumio go-librespot[8159]: time="2025-04-16T15:09:48+07:00" level=debug msg="completed challenge" Apr 16 15:09:48 volumio go-librespot[8159]: time="2025-04-16T15:09:48+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:49 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:49 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 200. Apr 16 15:09:51 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:51 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:51 volumio go-librespot[8177]: Librespot-go daemon starting... Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=info msg="generated new device id: 7beba1edc57fcf67038bee4112f2313e8f695449" Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=debug msg="zeroconf server listening on port 35787" Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=debug msg="obtained new client token: AABJ9OXCW0cbmkNA4JsuVsBzDfA62wsUNMW405KoXylZXtYsvw+BStSteHnOOVcxU378Zu6xnSHsdPvrtVNHD49gjg3p+R7jGGdTkZ3UTYIkXFFarEACKwIyhSpNkwIQpS60XwoECJlAtloodCprr567C/Cq3npljGSdiTft1am5Sn9JLSKqiO9jMwcYI0KzJ0KZRlqguKQnDW3fdWSXHNvHWazRnv+AdnF0g/hpziUK3tQcNRdXu58=" Apr 16 15:09:51 volumio go-librespot[8177]: time="2025-04-16T15:09:51+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:52 volumio go-librespot[8177]: time="2025-04-16T15:09:52+07:00" level=debug msg="completed challenge" Apr 16 15:09:52 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 16 15:09:52 volumio volumio[1080]: info: CURURI: genres:// Apr 16 15:09:52 volumio go-librespot[8177]: time="2025-04-16T15:09:52+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:52 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:52 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:52 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:52 volumio volumio[1080]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/fa-tags.svg' Apr 16 15:09:55 volumio volumio[1080]: info: Initializing connection to go-librespot Websocket Apr 16 15:09:55 volumio volumio[1080]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 15:09:55 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 15:09:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 201. Apr 16 15:09:55 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 15:09:55 volumio systemd[1]: Started go-librespot Daemon. Apr 16 15:09:55 volumio go-librespot[8207]: Librespot-go daemon starting... Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=info msg="generated new device id: 2c6d1bf8d57402e1c3c01b6b8e88c063c6a04609" Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=debug msg="zeroconf server listening on port 40553" Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=debug msg="obtained new client token: AAA65rZWvveJ+DUpgOCTzTSpFDWiOF70Zh2jjUMlJst9+aLqXgypjxeScvakp4gyI+9eC937U0m7LqgPtmvpSUHPSdza1lwrhTUattq0Yspo5MZ4WFkxijEt/7PDn51wrzspAak6Ce+AU5JTK3DGbvHJfmUD7aQ9PQ2J1ltz5ciTujL0SrNGaXZHh0TY5MR17gFH94j3V4c1mBmT+zk1Slw0fKXUEQ207wJhV0LDG+NqiYESo2ZWGKA=" Apr 16 15:09:55 volumio volumio[1080]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 16 15:09:55 volumio volumio[1080]: info: CURURI: genres://Acoustic Apr 16 15:09:55 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:55 volumio volumio[1080]: info: Preload queue cleared Apr 16 15:09:55 volumio go-librespot[8207]: time="2025-04-16T15:09:55+07:00" level=debug msg="completed keyexchange" Apr 16 15:09:56 volumio go-librespot[8207]: time="2025-04-16T15:09:56+07:00" level=debug msg="completed challenge" Apr 16 15:09:56 volumio go-librespot[8207]: time="2025-04-16T15:09:56+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 16 15:09:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 15:09:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 15:09:56 volumio volumio[1080]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 15:09:56 volumio volumio[1080]: Error: connect ETIMEDOUT 151.101.78.79:80 Apr 16 15:09:56 volumio volumio[1080]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Apr 16 15:09:56 volumio volumio[1080]: errno: -110, Apr 16 15:09:56 volumio volumio[1080]: code: 'ETIMEDOUT', Apr 16 15:09:56 volumio volumio[1080]: syscall: 'connect', Apr 16 15:09:56 volumio volumio[1080]: address: '151.101.78.79', Apr 16 15:09:56 volumio volumio[1080]: port: 80 Apr 16 15:09:56 volumio volumio[1080]: } Apr 16 15:09:56 volumio volumio[1080]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 15:09:56 volumio sudo[8226]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-16 15:08 Apr 16 15:09:56 volumio sudo[8226]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="e32c2c71ae78852844c70357816bdd871c155ab8" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 07:27:48 PM CEST" VOLUMIO_VERSION="3.799" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="4bc1ecb08f34ad14b420d6678a2aef1b"