-- Logs begin at Wed 2024-09-04 15:57:21 CEST, end at Wed 2024-09-04 20:18:21 CEST. -- Sep 04 20:17:02 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:02 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:02 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:02 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283243. Sep 04 20:17:02 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:02 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:02 volumio-odroid go-librespot[4307]: Librespot-go daemon starting... Sep 04 20:17:02 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:02+02:00" level=info msg="generated new device id: 6837ca624a13fac064ddb6c89bff9620966a3964" Sep 04 20:17:02 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:02+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:03 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:03+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gue1.spotify.com:443 ap2-gew1.spotify.com:80]" Sep 04 20:17:03 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:03+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Sep 04 20:17:03 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:03+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Sep 04 20:17:03 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:03+02:00" level=debug msg="zeroconf server listening on port 41391" Sep 04 20:17:05 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:05 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:05+02:00" level=debug msg="new websocket client" Sep 04 20:17:05 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket established Sep 04 20:17:07 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:07+02:00" level=debug msg="obtained new client token: AACcpoYDfNyoYCQWT7zOOPl57afbqrKI8tL8hEQoT/qDsBdqr1I3X7XpniD1aSqbuKz/sAKl3ld8q4lN4YaivhfV0I1Stq1hdEDkwkPyWZrWV5eLe3FCIpxwxsc0fVBUuOVvZMHPPyRCXZnks8rFkXu1J8Os9MZjGkVdEfvlL4zA7JMFpF8sYyzRwsCHXtOMSfyRu6v69shFq001vgyuD8B7t156yn9wGnXwkwMp3G9Rs5hFPGQcs7I=" Sep 04 20:17:07 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:07+02:00" level=debug msg="completed keyexchange" Sep 04 20:17:07 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:07+02:00" level=debug msg="completed challenge" Sep 04 20:17:08 volumio-odroid go-librespot[4307]: time="2024-09-04T20:17:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 04 20:17:08 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:08 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:08 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket closed Sep 04 20:17:08 volumio-odroid volumio[2764]: info: Getting Spotify volume Sep 04 20:17:08 volumio-odroid volumio[2764]: (node:2764) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:08 volumio-odroid volumio[2764]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Sep 04 20:17:08 volumio-odroid volumio[2764]: (node:2764) 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: 91106) Sep 04 20:17:08 volumio-odroid volumio[2764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 04 20:17:08 volumio-odroid volumio[2764]: info: CoreCommandRouter::volumioGetState Sep 04 20:17:11 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:11 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:11 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:11 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283244. Sep 04 20:17:11 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:11 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:11 volumio-odroid go-librespot[4324]: Librespot-go daemon starting... Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=info msg="generated new device id: 48479bbf50d6f2f754dcb2e75f8d9c70ed7607bc" Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gew1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=debug msg="zeroconf server listening on port 39993" Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=debug msg="obtained new client token: AACH9fuCzhhvgtN9wQRloHyNKlBnNg9OG1q2A4/BjZw8nPst3kLmQobKVXfldmylRd2HyGtNsdT3R6Mja1j7g/rlbyKcT8HudcArDY0PWcTR7QsbdgEGNAUOP4mf18gcf4MPoz5GsD6i5JHyBP9rY/16qq7xs64YJJ4HAF4AO7Ohgx23PgVlk8nz2pLmEOI0FgY/CafgTHh6LmtJeiK1ePOvSF4hjSWUnsWDiYu47+u1dBD2rqxebMT6AA==" Sep 04 20:17:11 volumio-odroid go-librespot[4324]: time="2024-09-04T20:17:11+02:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Sep 04 20:17:11 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:11 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:14 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:14 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:14 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:14 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283245. Sep 04 20:17:14 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:14 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:14 volumio-odroid go-librespot[4342]: Librespot-go daemon starting... Sep 04 20:17:14 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:14+02:00" level=info msg="generated new device id: 797fecfc5eeaf5da02dab989d12ef7384b472207" Sep 04 20:17:14 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:14+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:14 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:14+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gew1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 04 20:17:14 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:14+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 04 20:17:14 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:14+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 04 20:17:14 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:14+02:00" level=debug msg="zeroconf server listening on port 39905" Sep 04 20:17:15 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:15+02:00" level=debug msg="obtained new client token: AABUkQ2VxUrSKFMcH4Jvycseb5n/XfJIoyI0gKtQwiWA81KgHKh8El0Wkre4su8aVOCAmnX5t75YDJr6HBSLKSXg7yTZnzVCbKxD8D+lLGkgbGo09ecbBPCtXdFAQ/h1QkBEe7pulO2WFoH01XmKwo/E5UR0Qn27iRQheaYQleM/9mzIHwlkUPlv0drYHPHo4ddJh8LkInTSO9wq+/QmGK/mSn8qM2gcD9t/seLATGnMNVrtChOm/ZgvmA==" Sep 04 20:17:15 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:15+02:00" level=debug msg="completed keyexchange" Sep 04 20:17:15 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:15+02:00" level=debug msg="completed challenge" Sep 04 20:17:16 volumio-odroid go-librespot[4342]: time="2024-09-04T20:17:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 04 20:17:16 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:16 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:17 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:17 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:19 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:19 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283246. Sep 04 20:17:19 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:19 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:19 volumio-odroid go-librespot[4356]: Librespot-go daemon starting... Sep 04 20:17:19 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:19+02:00" level=info msg="generated new device id: 8350956642f36409102329bfd0ad277db9c45c78" Sep 04 20:17:19 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:19+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:20 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:20+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gew1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 04 20:17:20 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:20+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 04 20:17:20 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:20+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 04 20:17:20 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:20+02:00" level=debug msg="zeroconf server listening on port 36695" Sep 04 20:17:20 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:20 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:20+02:00" level=debug msg="new websocket client" Sep 04 20:17:20 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket established Sep 04 20:17:20 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:20+02:00" level=debug msg="obtained new client token: AABRP8CHJ2Fr6DFVKC7TpF7K1PMAJaD+3BnykD6czBD1fDNtVdsinEFQz2BW+0BVloqWx6DNyDBJ8Fh+oo2G1ZELfwet90DMo4/X0n4hRrVWgq1mgrjBT3sM5I6bmoNxySseZ/3fJ4bP/0ceS7sEwP23fqvx+NbqqVyVa50KQPlW/5MScHbN+EnqvnAYzj6M0m3ty614K4fVkC0GAvkrIS5W64+phN5PTcA8AmBTREPsQN1q4nNrUwDbug==" Sep 04 20:17:20 volumio-odroid go-librespot[4356]: time="2024-09-04T20:17:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Sep 04 20:17:20 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket closed Sep 04 20:17:20 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:20 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:23 volumio-odroid volumio[2764]: info: Getting Spotify volume Sep 04 20:17:23 volumio-odroid volumio[2764]: (node:2764) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:23 volumio-odroid volumio[2764]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Sep 04 20:17:23 volumio-odroid volumio[2764]: (node:2764) 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: 91107) Sep 04 20:17:23 volumio-odroid volumio[2764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 04 20:17:23 volumio-odroid volumio[2764]: info: CoreCommandRouter::volumioGetState Sep 04 20:17:23 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:23 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:23 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:23 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283247. Sep 04 20:17:23 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:23 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:23 volumio-odroid go-librespot[4373]: Librespot-go daemon starting... Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=info msg="generated new device id: 770f98022fc9be30504fdfbd906dba8bd8644fd9" Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gue1.spotify.com:443 ap2-gew1.spotify.com:80]" Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=debug msg="zeroconf server listening on port 39099" Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=debug msg="obtained new client token: AAAAXP1i3xuGkq7fstc6XsdfnQ76dpAjeelnOAebFaWgcfHqOE+cOBpuT4CW8JMlQeki5772AXY4Lu8rwKvGuWAtC2gO/8Who8sZsRnmRWrLry2zOYGQW4k7Ns2U+xtPNYgpOUvLIaVFyT+lpnaGJIgXh5IbzPlzh4Mt55BMOP41IDsJ/ighrQ7o3fPV5yQ+Ot0wOn1w3J1HKpS4RDgCkEvBbZiIHaLuUDQWBjM+7jTFSGkm8E7Q2s8lpg==" Sep 04 20:17:23 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:23+02:00" level=debug msg="completed keyexchange" Sep 04 20:17:24 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:24+02:00" level=debug msg="completed challenge" Sep 04 20:17:24 volumio-odroid go-librespot[4373]: time="2024-09-04T20:17:24+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 04 20:17:24 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:24 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:26 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:26 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:27 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:27 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283248. Sep 04 20:17:27 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:27 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:27 volumio-odroid go-librespot[4384]: Librespot-go daemon starting... Sep 04 20:17:27 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:27+02:00" level=info msg="generated new device id: ae6923edb04a206e0629583a6548881c3ccdbc64" Sep 04 20:17:27 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:27+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-gue1.spotify.com:4070 ap2-gew1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=debug msg="zeroconf server listening on port 37791" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=debug msg="obtained new client token: AAAAODKmtHAIAV0yAwl7MGO52laxcANYLGu/+yUmA24NH7+89HNdvY1cHz/nZv39mKlYSD4ewJeD6SoI+8s1Owm3s05wk7tHr7bHcx/SsMnJ7VUxYn+YgnC+XjoQV+mitXzoJTvZZn1RZ+gZXZ5aanzgQQ5fxi02v8uJYzBHGHKiSZvnfmi/wCAwxsO56iv6OY2j/UNO6HCYjJ/INqcpm4O4bA+q4INeMTY8fAPXjgKji/FeTD3Oa8o=" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=debug msg="completed keyexchange" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=debug msg="completed challenge" Sep 04 20:17:28 volumio-odroid go-librespot[4384]: time="2024-09-04T20:17:28+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 04 20:17:28 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:28 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:29 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:29 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:32 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:32 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283249. Sep 04 20:17:32 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:32 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:32 volumio-odroid go-librespot[4392]: Librespot-go daemon starting... Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=info msg="generated new device id: da72e1912c695f0fa920fc547cf55329c305e7d4" Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-gue1.spotify.com:4070 ap2-gew1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="zeroconf server listening on port 36959" Sep 04 20:17:32 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="new websocket client" Sep 04 20:17:32 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket established Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="obtained new client token: AAD3MvokJjPH4/WAv8O0N+CD80IzLJNSQjfLo+pFyQylm5GQhLkLStZYDIJHFQko3TQJwTuurSft99Gbf0d1z/rTjnmzeYGfGBew1EftOm33lMccFh4559dICCpNnumc5JSMbAXwVo8+46EV0tUW53ERBuvmkNAI4NNlxo4GNXLI33qI/HsGstTG+GSz9mS5NpEdD7Up1y0bTY1eGPZzvrc5pgVgOTaHDjWDUPRvfehQURIVo4BWWKSe6g==" Sep 04 20:17:32 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:32+02:00" level=debug msg="completed keyexchange" Sep 04 20:17:33 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:33+02:00" level=debug msg="completed challenge" Sep 04 20:17:33 volumio-odroid go-librespot[4392]: time="2024-09-04T20:17:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 04 20:17:33 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:33 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:33 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket closed Sep 04 20:17:35 volumio-odroid volumio[2764]: info: Getting Spotify volume Sep 04 20:17:35 volumio-odroid volumio[2764]: (node:2764) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:35 volumio-odroid volumio[2764]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Sep 04 20:17:35 volumio-odroid volumio[2764]: (node:2764) 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: 91108) Sep 04 20:17:35 volumio-odroid volumio[2764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 04 20:17:35 volumio-odroid volumio[2764]: info: CoreCommandRouter::volumioGetState Sep 04 20:17:36 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:36 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:36 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:36 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283250. Sep 04 20:17:36 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:36 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:36 volumio-odroid go-librespot[4407]: Librespot-go daemon starting... Sep 04 20:17:36 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:36+02:00" level=info msg="generated new device id: d44bda48e355212d7d2d0967ed886531e8cc89c3" Sep 04 20:17:36 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:36+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:36 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:36+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gue1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 04 20:17:36 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:36+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 04 20:17:36 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:36+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 04 20:17:36 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:36+02:00" level=debug msg="zeroconf server listening on port 36137" Sep 04 20:17:39 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:39 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:39+02:00" level=debug msg="new websocket client" Sep 04 20:17:39 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket established Sep 04 20:17:39 volumio-odroid volumio[2764]: info: Tunnel connection is inactive, restarting it Sep 04 20:17:39 volumio-odroid volumio[2764]: info: Starting Tunnel 1 Sep 04 20:17:39 volumio-odroid volumio[2764]: info: Starting Tunnel Connection Checker Sep 04 20:17:39 volumio-odroid sudo[4422]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Sep 04 20:17:39 volumio-odroid sudo[4422]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:17:39 volumio-odroid autossh[4138]: received signal to exit (15) Sep 04 20:17:39 volumio-odroid systemd[1]: Stopping MyVolumio SSH Tunnel... Sep 04 20:17:39 volumio-odroid volumio[2764]: ------------------------------------ BT MESSAGE: BT STATUS: running Sep 04 20:17:39 volumio-odroid systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM Sep 04 20:17:39 volumio-odroid systemd[1]: sshtunnel.service: Succeeded. Sep 04 20:17:39 volumio-odroid systemd[1]: Stopped MyVolumio SSH Tunnel. Sep 04 20:17:39 volumio-odroid volumio[2764]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Sep 04 20:17:39 volumio-odroid systemd[1]: Started MyVolumio SSH Tunnel. Sep 04 20:17:39 volumio-odroid sudo[4422]: pam_unix(sudo:session): session closed for user root Sep 04 20:17:39 volumio-odroid volumio[2764]: info: Remote SSH Started Sep 04 20:17:39 volumio-odroid volumio[2764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 04 20:17:39 volumio-odroid autossh[4425]: port set to 0, monitoring disabled Sep 04 20:17:39 volumio-odroid autossh[4425]: starting ssh (count 1) Sep 04 20:17:39 volumio-odroid autossh[4425]: ssh child pid is 4428 Sep 04 20:17:39 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:39+02:00" level=debug msg="obtained new client token: AABUMKPAt8eFkeJBKFzfe1lq2JGNPI7S8FbgRiOYEiEZB1NLOFMK3H5cFVtFhYbavxL5kK/KczPksgoa6HBZ8SQaCpKCFOXwXmUbSpeJ+LZU2H6PPmiuD6MIh0LpblY2Po8hOVqkKP1ngIVCYuOSNQjEj2MLpsJunEKnIbEcxNpVyB2XJz5sS/+LUh47baw+qwnLoFJeHyEMxthYDt81cPxRILY0qWO6WlvVrRDR4H5PAnfnpIxth52bkw==" Sep 04 20:17:40 volumio-odroid volumio[2764]: info: CoreCommandRouter::volumioGetState Sep 04 20:17:40 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:40+02:00" level=debug msg="completed keyexchange" Sep 04 20:17:40 volumio-odroid volumiossh-tunnel[4424]: Warning: Permanently added '[eu10.myvolumio.org]:2222,[46.101.141.203]:2222' (RSA) to the list of known hosts. Sep 04 20:17:40 volumio-odroid volumiossh-tunnel[4424]: Warning: remote port forwarding failed for listen port 8091 Sep 04 20:17:40 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:40+02:00" level=debug msg="completed challenge" Sep 04 20:17:40 volumio-odroid go-librespot[4407]: time="2024-09-04T20:17:40+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Sep 04 20:17:40 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:17:40 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:17:40 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket closed Sep 04 20:17:42 volumio-odroid volumio[2764]: info: Getting Spotify volume Sep 04 20:17:42 volumio-odroid volumio[2764]: (node:2764) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:42 volumio-odroid volumio[2764]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Sep 04 20:17:42 volumio-odroid volumio[2764]: (node:2764) 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: 91109) Sep 04 20:17:42 volumio-odroid volumio[2764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 04 20:17:42 volumio-odroid volumio[2764]: info: CoreCommandRouter::volumioGetState Sep 04 20:17:43 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:43 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:17:44 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:17:44 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283251. Sep 04 20:17:44 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:17:44 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:17:44 volumio-odroid go-librespot[4429]: Librespot-go daemon starting... Sep 04 20:17:44 volumio-odroid go-librespot[4429]: time="2024-09-04T20:17:44+02:00" level=info msg="generated new device id: 22108ef6fc11ac4c43bdbffe22347d1a43b33441" Sep 04 20:17:44 volumio-odroid go-librespot[4429]: time="2024-09-04T20:17:44+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:17:44 volumio-odroid go-librespot[4429]: time="2024-09-04T20:17:44+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gue1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 04 20:17:44 volumio-odroid go-librespot[4429]: time="2024-09-04T20:17:44+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Sep 04 20:17:44 volumio-odroid go-librespot[4429]: time="2024-09-04T20:17:44+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Sep 04 20:17:44 volumio-odroid go-librespot[4429]: time="2024-09-04T20:17:44+02:00" level=debug msg="zeroconf server listening on port 37033" Sep 04 20:17:46 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:17:46 volumio-odroid go-librespot[4429]: time="2024-09-04T20:17:46+02:00" level=debug msg="new websocket client" Sep 04 20:17:46 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket established Sep 04 20:17:49 volumio-odroid volumio[2764]: info: Getting Spotify volume Sep 04 20:17:49 volumio-odroid volumio[2764]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 04 20:17:49 volumio-odroid volumio[2764]: info: CoreCommandRouter::volumioGetState Sep 04 20:18:06 volumio-odroid wpa_supplicant[2619]: wlan0: CTRL-EVENT-DISCONNECTED bssid=04:42:1a:6b:e6:c4 reason=0 Sep 04 20:18:06 volumio-odroid dhcpcd[2461]: wlan0: carrier lost Sep 04 20:18:06 volumio-odroid wpa_supplicant[2619]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Sep 04 20:18:06 volumio-odroid avahi-daemon[2317]: Withdrawing address record for 192.168.50.231 on wlan0. Sep 04 20:18:06 volumio-odroid avahi-daemon[2317]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.231. Sep 04 20:18:06 volumio-odroid volumio[2764]: info: Discovery: A device disappeared from network Sep 04 20:18:06 volumio-odroid avahi-daemon[2317]: Interface wlan0.IPv4 no longer relevant for mDNS. Sep 04 20:18:06 volumio-odroid wpa_supplicant[2619]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=DE Sep 04 20:18:06 volumio-odroid dhcpcd[2461]: eth0: changing default route Sep 04 20:18:06 volumio-odroid dhcpcd[2461]: if_route (ADD): Invalid argument Sep 04 20:18:06 volumio-odroid dhcpcd[2461]: eth0: deleting route to 192.168.50.0/24 Sep 04 20:18:06 volumio-odroid dhcpcd[2461]: eth0: deleting default route via 192.168.50.1 Sep 04 20:18:06 volumio-odroid dhcpcd[2664]: eth0: deleted route to 192.168.50.0/24 Sep 04 20:18:06 volumio-odroid dhcpcd[2461]: wlan0: deleting route to 192.168.50.0/24 Sep 04 20:18:06 volumio-odroid dhcpcd[2664]: eth0: deleted default route via 192.168.50.1 Sep 04 20:18:06 volumio-odroid dhcpcd[2461]: wlan0: deleting default route via 192.168.50.1 Sep 04 20:18:07 volumio-odroid go-librespot[4429]: time="2024-09-04T20:18:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed obtaining client token: failed requesting clienttoken: Post \"https://clienttoken.spotify.com/v1/clienttoken\": dial tcp: lookup clienttoken.spotify.com: device or resource busy" Sep 04 20:18:07 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:18:07 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:18:07 volumio-odroid volumio[2764]: (node:2764) UnhandledPromiseRejectionWarning: Error: socket hang up Sep 04 20:18:07 volumio-odroid volumio[2764]: at connResetException (internal/errors.js:639:14) Sep 04 20:18:07 volumio-odroid volumio[2764]: at Socket.socketOnEnd (_http_client.js:499:23) Sep 04 20:18:07 volumio-odroid volumio[2764]: at Socket.emit (events.js:412:35) Sep 04 20:18:07 volumio-odroid volumio[2764]: at endReadableNT (internal/streams/readable.js:1333:12) Sep 04 20:18:07 volumio-odroid volumio[2764]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Sep 04 20:18:07 volumio-odroid volumio[2764]: (node:2764) 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: 91110) Sep 04 20:18:07 volumio-odroid volumio[2764]: info: Connection to go-librespot Websocket closed Sep 04 20:18:08 volumio-odroid ntpd[3820]: Deleting interface #4 wlan0, 192.168.50.231#123, interface stats: received=0, sent=0, dropped=0, active_time=312 secs Sep 04 20:18:10 volumio-odroid volumio[2764]: info: Initializing connection to go-librespot Websocket Sep 04 20:18:10 volumio-odroid volumio[2764]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 20:18:10 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:18:10 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283252. Sep 04 20:18:10 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:18:10 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:18:10 volumio-odroid go-librespot[4518]: Librespot-go daemon starting... Sep 04 20:18:10 volumio-odroid go-librespot[4518]: time="2024-09-04T20:18:10+02:00" level=info msg="generated new device id: c4dcf0c1dc1f2efa174c019ae056eed8db5f565e" Sep 04 20:18:10 volumio-odroid go-librespot[4518]: time="2024-09-04T20:18:10+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:18:10 volumio-odroid go-librespot[4518]: time="2024-09-04T20:18:10+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Sep 04 20:18:10 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:18:10 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:18:11 volumio-odroid volumio[2764]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 20:18:11 volumio-odroid volumio[2764]: Error: send ENETUNREACH 255.255.255.255:3483 Sep 04 20:18:11 volumio-odroid volumio[2764]: at doSend (dgram.js:714:16) Sep 04 20:18:11 volumio-odroid volumio[2764]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:452:18) Sep 04 20:18:11 volumio-odroid volumio[2764]: at afterDns (dgram.js:660:5) Sep 04 20:18:11 volumio-odroid volumio[2764]: at processTicksAndRejections (internal/process/task_queues.js:83:21) { Sep 04 20:18:11 volumio-odroid volumio[2764]: errno: -101, Sep 04 20:18:11 volumio-odroid volumio[2764]: code: 'ENETUNREACH', Sep 04 20:18:11 volumio-odroid volumio[2764]: syscall: 'send', Sep 04 20:18:11 volumio-odroid volumio[2764]: address: '255.255.255.255', Sep 04 20:18:11 volumio-odroid volumio[2764]: port: 3483 Sep 04 20:18:11 volumio-odroid volumio[2764]: } Sep 04 20:18:11 volumio-odroid volumio[2764]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 20:18:12 volumio-odroid sudo[4537]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-04 20:17 Sep 04 20:18:12 volumio-odroid sudo[4537]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:12 volumio-odroid sudo[4537]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:12 volumio-odroid volumio-remote-updater[2332]: [2024-09-04 20:18:12] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Sep 04 20:18:12 volumio-odroid volumio-remote-updater[2332]: [2024-09-04 20:18:12] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Sep 04 20:18:12 volumio-odroid vtcs[3413]: [2024-09-04 20:18:12.348] [tisoc] [error] [SpkconServer.cpp:376] recv error. socket disconnected Sep 04 20:18:12 volumio-odroid systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:18:12 volumio-odroid systemd[1]: volumio.service: Failed with result 'exit-code'. Sep 04 20:18:12 volumio-odroid systemd[1]: Started dynamicswap service. Sep 04 20:18:12 volumio-odroid systemd[1]: dynamicswap.service: Succeeded. Sep 04 20:18:12 volumio-odroid systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Sep 04 20:18:12 volumio-odroid systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Sep 04 20:18:12 volumio-odroid systemd[1]: Started dynamicswap service. Sep 04 20:18:12 volumio-odroid systemd[1]: Stopped Volumio Backend Module. Sep 04 20:18:12 volumio-odroid systemd[1]: Started Volumio Backend Module. Sep 04 20:18:12 volumio-odroid systemd[1]: dynamicswap.service: Succeeded. Sep 04 20:18:13 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:18:13 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283253. Sep 04 20:18:13 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:18:13 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:18:13 volumio-odroid go-librespot[4563]: Librespot-go daemon starting... Sep 04 20:18:13 volumio-odroid go-librespot[4563]: time="2024-09-04T20:18:13+02:00" level=info msg="generated new device id: 2e409012ac99ddb679f013bd5eb12cd1820d4310" Sep 04 20:18:13 volumio-odroid go-librespot[4563]: time="2024-09-04T20:18:13+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:18:13 volumio-odroid go-librespot[4563]: time="2024-09-04T20:18:13+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Sep 04 20:18:13 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:18:13 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:18:14 volumio-odroid volumio[4551]: info: ------------------------------------------- Sep 04 20:18:14 volumio-odroid volumio[4551]: info: ----- Volumio3 ---- Sep 04 20:18:14 volumio-odroid volumio[4551]: info: ------------------------------------------- Sep 04 20:18:14 volumio-odroid volumio[4551]: info: ----- System startup ---- Sep 04 20:18:14 volumio-odroid volumio[4551]: info: ------------------------------------------- Sep 04 20:18:15 volumio-odroid volumio[4551]: info: MYVOLUMIO Environment detected Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Plugin folders cleanup Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning into folder /volumio/app/plugins/ Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning category audio_interface Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning category miscellanea Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning category music_service Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning category plugins.json Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning category system_controller Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning category user_interface Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning into folder /data/plugins/ Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Scanning category music_service Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Plugin folders cleanup completed Sep 04 20:18:15 volumio-odroid volumio[4551]: info: ------------------------------------------- Sep 04 20:18:15 volumio-odroid volumio[4551]: info: ----- Core plugins startup ---- Sep 04 20:18:15 volumio-odroid volumio[4551]: info: ------------------------------------------- Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Loading plugins from folder /volumio/app/plugins/ Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Adding plugin upnp to MyMusic Plugins Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Adding plugin airplay_emulation to MyMusic Plugins Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Adding plugin upnp_browser to MyMusic Plugins Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Loading plugins from folder /data/plugins/ Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Loading plugin "system"... Sep 04 20:18:15 volumio-odroid volumio[4551]: info: Loading plugin "appearance"... Sep 04 20:18:15 volumio-odroid wpa_supplicant[2619]: wlan0: Trying to associate with ca:42:1a:6b:d0:94 (SSID='Radio Gnome Invisible 5GHz' freq=5200 MHz) Sep 04 20:18:15 volumio-odroid wpa_supplicant[2619]: wlan0: Associated with ca:42:1a:6b:d0:94 Sep 04 20:18:15 volumio-odroid wpa_supplicant[2619]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Sep 04 20:18:15 volumio-odroid wpa_supplicant[2619]: wlan0: WPA: Key negotiation completed with ca:42:1a:6b:d0:94 [PTK=CCMP GTK=CCMP] Sep 04 20:18:15 volumio-odroid wpa_supplicant[2619]: wlan0: CTRL-EVENT-CONNECTED - Connection to ca:42:1a:6b:d0:94 completed [id=0 id_str=] Sep 04 20:18:15 volumio-odroid dhcpcd[2461]: wlan0: carrier acquired Sep 04 20:18:15 volumio-odroid wpa_supplicant[2619]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=DE Sep 04 20:18:15 volumio-odroid dhcpcd[2461]: wlan0: IAID a9:3a:1c:52 Sep 04 20:18:16 volumio-odroid dhcpcd[2461]: wlan0: soliciting an IPv6 router Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "network"... Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Refreshing Cached IP Addresses Sep 04 20:18:16 volumio-odroid sudo[4587]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 04 20:18:16 volumio-odroid sudo[4587]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:16 volumio-odroid sudo[4587]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:16 volumio-odroid sudo[4589]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "services"... Sep 04 20:18:16 volumio-odroid sudo[4589]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:16 volumio-odroid dhcpcd[2461]: wlan0: rebinding lease of 192.168.50.231 Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "alsa_controller"... Sep 04 20:18:16 volumio-odroid sudo[4589]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:16 volumio-odroid sudo[4592]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Sep 04 20:18:16 volumio-odroid sudo[4592]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:16 volumio-odroid dhcpcd[2461]: wlan0: probing address 192.168.50.231/24 Sep 04 20:18:16 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "wizard"... Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "networkfs"... Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Cannot mount NAS Music at system boot, trial number 1 ,retrying in 5 seconds Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Starting Udev Watcher for removable devices Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Ignoring mount for partition: boot Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Ignoring mount for partition: volumio Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Ignoring mount for partition: volumio_data Sep 04 20:18:16 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "volumio_command_line_client"... Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "upnp"... Sep 04 20:18:16 volumio-odroid volumio[4551]: info: [1725473896367] Starting Upmpd Daemon Sep 04 20:18:16 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "my_music"... Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "mpd"... Sep 04 20:18:16 volumio-odroid sudo[4592]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:16 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:18:16 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283254. Sep 04 20:18:16 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:18:16 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:18:16 volumio-odroid go-librespot[4597]: Librespot-go daemon starting... Sep 04 20:18:16 volumio-odroid go-librespot[4597]: time="2024-09-04T20:18:16+02:00" level=info msg="generated new device id: a6527512520ff04a985611b4571a84cf9efa0e6b" Sep 04 20:18:16 volumio-odroid go-librespot[4597]: time="2024-09-04T20:18:16+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:18:16 volumio-odroid go-librespot[4597]: time="2024-09-04T20:18:16+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Sep 04 20:18:16 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:18:16 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "upnp_browser"... Sep 04 20:18:16 volumio-odroid volumio[4551]: info: Loading plugin "alarm-clock"... Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Loading plugin "airplay_emulation"... Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Starting Shairport Sync Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Loading plugin "last_100"... Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Loading plugin "webradio"... Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Loading plugin "i2s_dacs"... Sep 04 20:18:17 volumio-odroid volumio[4551]: info: I2S DAC not set, start Auto-detection Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Loading plugin "volumiodiscovery"... Sep 04 20:18:17 volumio-odroid volumio[4551]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 04 20:18:17 volumio-odroid volumio[4551]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 04 20:18:17 volumio-odroid volumio[4551]: *** WARNING *** For more information see Sep 04 20:18:17 volumio-odroid volumio[4551]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 04 20:18:17 volumio-odroid node[4551]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Sep 04 20:18:17 volumio-odroid volumio[4551]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 04 20:18:17 volumio-odroid volumio[4551]: *** WARNING *** For more information see Sep 04 20:18:17 volumio-odroid node[4551]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 04 20:18:17 volumio-odroid node[4551]: *** WARNING *** For more information see Sep 04 20:18:17 volumio-odroid node[4551]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Sep 04 20:18:17 volumio-odroid node[4551]: *** WARNING *** Please fix your application to use the native API of Avahi! Sep 04 20:18:17 volumio-odroid node[4551]: *** WARNING *** For more information see Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Applying required configuration parameters for plugin volumiodiscovery Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Discovery: Started advertising with name: Volumio-odroid Sep 04 20:18:17 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Sep 04 20:18:17 volumio-odroid volumio[4551]: info: Loading plugin "spop"... Sep 04 20:18:17 volumio-odroid volumio-remote-updater[2332]: [2024-09-04 20:18:17] [connect] Successful connection Sep 04 20:18:18 volumio-odroid volumio[4551]: info: Loading plugin "squeezelite_mc"... Sep 04 20:18:18 volumio-odroid volumio[4551]: info: Loading plugin "outputs"... Sep 04 20:18:18 volumio-odroid volumio[4551]: info: Loading plugin "albumart"... Sep 04 20:18:18 volumio-odroid volumio[4551]: info: Plugin example_plugin is not enabled Sep 04 20:18:18 volumio-odroid volumio[4551]: info: Loading plugin "inputs"... Sep 04 20:18:18 volumio-odroid volumio[4551]: info: Loading plugin "updater_comm"... Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Plugin mpdemulation is not enabled Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Loading plugin "rest_api"... Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Loading plugin "websocket"... Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Starting Socket.io Server version 2.3.0 Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Loading i18n strings for locale it Sep 04 20:18:19 volumio-odroid volumio[4551]: Updating browse sources language Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 04 20:18:19 volumio-odroid volumio[4551]: Forking 3 albumart workers Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::initPlayerControls Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: Express server listening on port 3000 Sep 04 20:18:19 volumio-odroid volumio[4551]: [Metrics] WebUI: 5s 604.02ms Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreStateMachine::resetVolumioState Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreStateMachine::getcurrentVolume Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioRetrievevolume Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreStateMachine::pushState Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CorePlayQueue::getTrack 0 Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioPushState Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 04 20:18:19 volumio-odroid volumio[4551]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Completed loading Core Plugins Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Preparing to generate the ALSA configuration file Sep 04 20:18:19 volumio-odroid volumio-remote-updater[2332]: [2024-09-04 20:18:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1725473897 101 Sep 04 20:18:19 volumio-odroid volumio[4551]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Reloading queue from file Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreStateMachine::setRepeat null single undefined Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreStateMachine::pushState Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CorePlayQueue::getTrack 0 Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioPushState Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreStateMachine::setRandom null Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreStateMachine::pushState Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CorePlayQueue::getTrack 0 Sep 04 20:18:19 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioPushState Sep 04 20:18:19 volumio-odroid systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 20:18:19 volumio-odroid systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 283255. Sep 04 20:18:19 volumio-odroid systemd[1]: Stopped go-librespot Daemon. Sep 04 20:18:19 volumio-odroid systemd[1]: Started go-librespot Daemon. Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Asound.conf file written Sep 04 20:18:19 volumio-odroid go-librespot[4644]: Librespot-go daemon starting... Sep 04 20:18:19 volumio-odroid go-librespot[4644]: time="2024-09-04T20:18:19+02:00" level=info msg="generated new device id: 66e25f8ade1cb2336f1225b02acebb1fd48663b3" Sep 04 20:18:19 volumio-odroid go-librespot[4644]: time="2024-09-04T20:18:19+02:00" level=debug msg="stored credentials found for gipus" Sep 04 20:18:19 volumio-odroid go-librespot[4644]: time="2024-09-04T20:18:19+02:00" level=fatal msg="failed running with username and spotify token" error="failed getting endpoints from resolver: failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint&type=dealer&type=spclient\": dial tcp: lookup apresolve.spotify.com: device or resource busy" Sep 04 20:18:19 volumio-odroid systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 20:18:19 volumio-odroid systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 20:18:19 volumio-odroid sudo[4652]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Sep 04 20:18:19 volumio-odroid sudo[4652]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:19 volumio-odroid sudo[4652]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:19 volumio-odroid kernel: out of value, fixed it Sep 04 20:18:19 volumio-odroid kernel: id=0 set inskew=0 Sep 04 20:18:19 volumio-odroid kernel: Fine tdm clk setting range (0~2000000), 11289593 Sep 04 20:18:19 volumio-odroid kernel: out of value, fixed it Sep 04 20:18:19 volumio-odroid kernel: id=0 set inskew=0 Sep 04 20:18:19 volumio-odroid volumio[4551]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:SPDIFIN audio samplerate:0' : Operation not permitted Sep 04 20:18:19 volumio-odroid volumio[4551]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:SPDIFIN Audio Type:0' : Operation not permitted Sep 04 20:18:19 volumio-odroid volumio[4551]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:I2SIn CLK:0' : Operation not permitted Sep 04 20:18:19 volumio-odroid volumio[4551]: info: Output device has changed, restarting MPD Sep 04 20:18:19 volumio-odroid volumio[4551]: Starting albumart workers Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Output device has changed, restarting Shairport Sync Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 04 20:18:20 volumio-odroid sudo[4658]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 04 20:18:20 volumio-odroid sudo[4658]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:20 volumio-odroid volumio[4551]: Starting albumart workers Sep 04 20:18:20 volumio-odroid volumio[4551]: Starting albumart workers Sep 04 20:18:20 volumio-odroid sudo[4659]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 04 20:18:20 volumio-odroid sudo[4659]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:20 volumio-odroid sudo[4658]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:20 volumio-odroid systemd[1]: Stopping Music Player Daemon... Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 04 20:18:20 volumio-odroid volumio[4551]: info: ___________ START PLUGINS ___________ Sep 04 20:18:20 volumio-odroid volumio[4551]: info: ControllerMpd::onStart: Initializing MPD Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Creating MPD Configuration file Sep 04 20:18:20 volumio-odroid systemd[1]: mpd.service: Succeeded. Sep 04 20:18:20 volumio-odroid systemd[1]: Stopped Music Player Daemon. Sep 04 20:18:20 volumio-odroid systemd[1]: Starting Music Player Daemon... Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [1725473900137] CoreMusicLibrary::Adding element Server multimediali Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 04 20:18:20 volumio-odroid sudo[4666]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 04 20:18:20 volumio-odroid sudo[4666]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:20 volumio-odroid sudo[4669]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 04 20:18:20 volumio-odroid sudo[4669]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:20 volumio-odroid sudo[4666]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 04 20:18:20 volumio-odroid systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Sep 04 20:18:20 volumio-odroid systemd[1]: mpd.service: Succeeded. Sep 04 20:18:20 volumio-odroid systemd[1]: Stopped Music Player Daemon. Sep 04 20:18:20 volumio-odroid systemd[1]: Starting Music Player Daemon... Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [1725473900356] CoreMusicLibrary::Adding element Last_100 Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [1725473900360] CoreMusicLibrary::Adding element Webradio Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 04 20:18:20 volumio-odroid sudo[4675]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 04 20:18:20 volumio-odroid sudo[4675]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Initializing BBC Radios Sep 04 20:18:20 volumio-odroid sudo[4675]: pam_unix(sudo:session): session closed for user root Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Creating Spotify config file Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [squeezelite_mc] Starting proxy server... Sep 04 20:18:20 volumio-odroid volumio[4551]: info: Volumio Calling Home Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [squeezelite_mc] Proxy server started on port 42371 Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioRetrievevolume Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreStateMachine::pushState Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CorePlayQueue::getTrack 0 Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::volumioPushState Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [squeezelite_mc] Server discovery started Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [squeezelite_mc] Player finder started Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Sep 04 20:18:20 volumio-odroid volumio[4551]: info: [squeezelite_mc] Executing aplay -D hw:1 --nonblock -f MPEG /dev/zero 2>&1 || true Sep 04 20:18:20 volumio-odroid volumio[4551]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 20:18:20 volumio-odroid volumio[4551]: Error: send ENETUNREACH 255.255.255.255:3483 Sep 04 20:18:20 volumio-odroid volumio[4551]: at doSend (dgram.js:714:16) Sep 04 20:18:20 volumio-odroid volumio[4551]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:452:18) Sep 04 20:18:20 volumio-odroid volumio[4551]: at afterDns (dgram.js:660:5) Sep 04 20:18:20 volumio-odroid volumio[4551]: at processTicksAndRejections (internal/process/task_queues.js:83:21) { Sep 04 20:18:20 volumio-odroid volumio[4551]: errno: -101, Sep 04 20:18:20 volumio-odroid volumio[4551]: code: 'ENETUNREACH', Sep 04 20:18:20 volumio-odroid volumio[4551]: syscall: 'send', Sep 04 20:18:20 volumio-odroid volumio[4551]: address: '255.255.255.255', Sep 04 20:18:20 volumio-odroid volumio[4551]: port: 3483 Sep 04 20:18:20 volumio-odroid volumio[4551]: } Sep 04 20:18:20 volumio-odroid volumio[4551]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 20:18:20 volumio-odroid kernel: aml_tdm_open Sep 04 20:18:20 volumio-odroid kernel: Not init audio effects Sep 04 20:18:20 volumio-odroid kernel: audio_ddr_mngr: frddrs[0] registered by device ff660000.audiobus:tdm@1 Sep 04 20:18:20 volumio-odroid kernel: pcm512x 0-004c: No SCLK, using BCLK: -2 Sep 04 20:18:20 volumio-odroid kernel: tdm playback mute: 1, lane_cnt = 8 Sep 04 20:18:20 volumio-odroid kernel: audio_ddr_mngr: frddrs[0] released by device ff660000.audiobus:tdm@1 Sep 04 20:18:21 volumio-odroid dhcpcd[2461]: wlan0: leased 192.168.50.231 for 86400 seconds Sep 04 20:18:21 volumio-odroid dhcpcd[2461]: wlan0: adding route to 192.168.50.0/24 Sep 04 20:18:21 volumio-odroid dhcpcd[2461]: wlan0: adding default route via 192.168.50.1 Sep 04 20:18:21 volumio-odroid avahi-daemon[2317]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.50.231. Sep 04 20:18:21 volumio-odroid avahi-daemon[2317]: New relevant interface wlan0.IPv4 for mDNS. Sep 04 20:18:21 volumio-odroid avahi-daemon[2317]: Registering new address record for 192.168.50.231 on wlan0.IPv4. Sep 04 20:18:21 volumio-odroid sudo[4741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-04 20:17 Sep 04 20:18:21 volumio-odroid sudo[4741]: 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="6e682b9410d28f3874f90b2d7789db824a859264" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="7c81f20187867c3bd55475ead0f12800fe93082c" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 08 Jun 2024 11:49:15 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="odroidc4" VOLUMIO_DEVICENAME="Odroid-C4" VOLUMIO_HASH="d2400f5f761721872d49eaefed0badd6"