-- Logs begin at Mon 2024-11-25 15:35:31 +07, end at Mon 2024-11-25 16:13:59 +07. -- Nov 25 16:12:00 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:00 volumio volumio[1130]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:12:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 592. Nov 25 16:12:02 volumio systemd[1]: Stopped go-librespot Daemon. Nov 25 16:12:02 volumio systemd[1]: Started go-librespot Daemon. Nov 25 16:12:02 volumio go-librespot[14736]: Librespot-go daemon starting... Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12:02+07:00" level=info msg="generated new device id: 29a44a150bffc48c1a3d6f46ef0b7c0f592457ba" Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12:02+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12: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]" Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12: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]" Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12: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]" Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12:02+07:00" level=debug msg="zeroconf server listening on port 36461" Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12:02+07:00" level=debug msg="obtained new client token: AAAf0qX/GthT/Y38mP+wEkVm4cp3Lk77q/6Rn1pMf6AmJ8Xmch7k7WpGaRgd9lBgpy4OaeSpx4/lBgO6i+YG3HWq7zfApk7uxkTDfNlKuJIa6OCXNb9F5FBXGcxnL0oJ+pn2aqk9n0IHYrTPpYAfhXgfgZ7eRLGvkvKs7G82Pt+JnVgPrmU3+QLj/Y0yZDuDY5eBPqrCVMLM682wmvzWssZSSLWNXhEKuSHt2CR83u4rxLp78XdbzbeZuDAXzg==" Nov 25 16:12:02 volumio go-librespot[14736]: time="2024-11-25T16:12:02+07:00" level=debug msg="completed keyexchange" Nov 25 16:12:03 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:03 volumio go-librespot[14736]: time="2024-11-25T16:12:03+07:00" level=debug msg="new websocket client" Nov 25 16:12:03 volumio volumio[1130]: info: Connection to go-librespot Websocket established Nov 25 16:12:03 volumio go-librespot[14736]: time="2024-11-25T16:12:03+07:00" level=debug msg="completed challenge" Nov 25 16:12:03 volumio go-librespot[14736]: time="2024-11-25T16:12: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" Nov 25 16:12:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:12:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:12:03 volumio volumio[1130]: info: Connection to go-librespot Websocket closed Nov 25 16:12:06 volumio volumio[1130]: info: Getting Spotify volume Nov 25 16:12:06 volumio volumio[1130]: (node:1130) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:06 volumio volumio[1130]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Nov 25 16:12:06 volumio volumio[1130]: (node:1130) 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: 109) Nov 25 16:12:06 volumio volumio[1130]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Nov 25 16:12:06 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:12:06 volumio volumio[1130]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 25 16:12:06 volumio volumio[1130]: SPOTIFY: SPOTIFY VOLUME 100 Nov 25 16:12:06 volumio volumio[1130]: SPOTIFY: VOLUMIO VOLUME 100 Nov 25 16:12:06 volumio volumio[1130]: SPOTIFY: DELTA VOLUME ENOUGH: false Nov 25 16:12:06 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:06 volumio volumio[1130]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:12:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 593. Nov 25 16:12:06 volumio systemd[1]: Stopped go-librespot Daemon. Nov 25 16:12:06 volumio systemd[1]: Started go-librespot Daemon. Nov 25 16:12:06 volumio go-librespot[14745]: Librespot-go daemon starting... Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+07:00" level=info msg="generated new device id: 39e838e9ce898f67dd96893c7c4ec55e4f233037" Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+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]" Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+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]" Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+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]" Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+07:00" level=debug msg="zeroconf server listening on port 35481" Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+07:00" level=debug msg="obtained new client token: AACu97b9iONS1/8xLLdvnYZRGQgUzGQSmyz3eoy7UV6hQSjMF1mdXbPl5ChzMlUFIUwDdatcsSm6457GvOJa6y6KY9Sq/A/8GteNdlDticxxdwyVf2qjWKoyxO7ux7vOovpa3QWQLS6ForG+H6C/6tfLmgapbiJ96YcUSpvmqUvaohCtd3qK8wWLHcGV6C54i4E0JgXwWZO9PJ8+USWzjDXub5v1QyRTDVMKmxSiClGGBR/A0gyqN+L1sKSvQw==" Nov 25 16:12:06 volumio go-librespot[14745]: time="2024-11-25T16:12:06+07:00" level=debug msg="completed keyexchange" Nov 25 16:12:07 volumio go-librespot[14745]: time="2024-11-25T16:12:07+07:00" level=debug msg="completed challenge" Nov 25 16:12:07 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Nov 25 16:12:07 volumio go-librespot[14745]: time="2024-11-25T16:12: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" Nov 25 16:12:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:12:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:12:07 volumio volumio[1130]: info: Received Get System Info Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 25 16:12:07 volumio volumio[1130]: info: Discovery: Getting this device information Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::volumioGetVisibleSources Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::volumioGetQueue Nov 25 16:12:07 volumio volumio[1130]: info: CoreStateMachine::getQueue Nov 25 16:12:07 volumio volumio[1130]: info: CorePlayQueue::getQueue Nov 25 16:12:07 volumio volumio[1130]: info: Listing playlists Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 25 16:12:07 volumio volumio[1130]: info: Received Get System Info Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 25 16:12:07 volumio volumio[1130]: info: Discovery: Getting this device information Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:07 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:12:08 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Nov 25 16:12:09 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:09 volumio volumio[1130]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:12:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 594. Nov 25 16:12:10 volumio systemd[1]: Stopped go-librespot Daemon. Nov 25 16:12:10 volumio systemd[1]: Started go-librespot Daemon. Nov 25 16:12:10 volumio go-librespot[14753]: Librespot-go daemon starting... Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+07:00" level=info msg="generated new device id: 24f97a5683b7aef5281f9bb08b3e1dad92adc6d7" Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+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]" Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+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]" Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+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]" Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+07:00" level=debug msg="zeroconf server listening on port 41921" Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+07:00" level=debug msg="obtained new client token: AABweljzxsLGFqP+n6i5UN8PJXBGXopiy0xq8ZBo2KJVbi5vR0O9dqDoJYlLNyYDbbp2uxe8jkn8FDUbaXWRbasqH/DnGUN6DwFpZmR7995r9DvGvkdCqyfMttUuP6MhwC9E6QdN7kUnPNtx1wc/gZJTgOwDe78wcYzJ9u55fQR89bxGnbv1WEM3yxDC5J2SCL6v1OyxZZcRwhYNLCAE9V/+anJcmdfs9Vpk33EqayRKxmMX4rX6AAgiFUl2DA==" Nov 25 16:12:10 volumio go-librespot[14753]: time="2024-11-25T16:12:10+07:00" level=debug msg="completed keyexchange" Nov 25 16:12:11 volumio go-librespot[14753]: time="2024-11-25T16:12:11+07:00" level=debug msg="completed challenge" Nov 25 16:12:11 volumio go-librespot[14753]: time="2024-11-25T16:12: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" Nov 25 16:12:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:12:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:12:12 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:12 volumio volumio[1130]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:12:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 595. Nov 25 16:12:14 volumio systemd[1]: Stopped go-librespot Daemon. Nov 25 16:12:14 volumio systemd[1]: Started go-librespot Daemon. Nov 25 16:12:14 volumio go-librespot[14761]: Librespot-go daemon starting... Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+07:00" level=info msg="generated new device id: 7ade674968560bfec9a8fd0b8c4df6225230c180" Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+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]" Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+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]" Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+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]" Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+07:00" level=debug msg="zeroconf server listening on port 38105" Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+07:00" level=debug msg="obtained new client token: AAD97vRF8XQKG127loJkVsK6bcuGrFVPKrbTlcVZIlad4znGuC0EhbnAI+sPLkz76OnEfBWpHUSojnFgp5i/Xg2RPTAHIfyBL1Z7kh1rLn3Y3YqfY93Ayq+C/CM7qQdyASBqLErLihtRySkqxkYif2bFeVExsea/5bjX9g0LI/1/JzXfajtM0WXV1cBSDrX2oh4E08J1c/N7nwroet6B0JG5CUC5Hd/K0nNZf7i5vHNFwHcd0X376Ww4e1bIPQ==" Nov 25 16:12:14 volumio go-librespot[14761]: time="2024-11-25T16:12:14+07:00" level=debug msg="completed keyexchange" Nov 25 16:12:15 volumio go-librespot[14761]: time="2024-11-25T16:12:15+07:00" level=debug msg="completed challenge" Nov 25 16:12:15 volumio go-librespot[14761]: time="2024-11-25T16:12: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" Nov 25 16:12:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:12:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:12:15 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:15 volumio volumio[1130]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:18 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:18 volumio volumio[1130]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:12:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 596. Nov 25 16:12:18 volumio systemd[1]: Stopped go-librespot Daemon. Nov 25 16:12:18 volumio systemd[1]: Started go-librespot Daemon. Nov 25 16:12:18 volumio go-librespot[14769]: Librespot-go daemon starting... Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+07:00" level=info msg="generated new device id: 8a9f277c189f504091e2f03b9467a3a4fa0c2162" Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+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]" Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+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]" Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+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]" Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+07:00" level=debug msg="zeroconf server listening on port 36035" Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+07:00" level=debug msg="obtained new client token: AADgf4BUlkSuhTRauM6WwPgEmYWzeKrOiT3zawX1XrXsICD3RZc6er4lqZwsygIF4++02cUiGid2tGjy5A+7EAVcfz3OP7jSGYSL62f2LaH6FGEOF1yS0174EEEK3Bc0YJm/NTBmo3KzsUZnzZ/UJOFochEVkZXkm9KKqiB5hgG5S44zxGh97VQM1w4ZwZIUfL+4aptnr7tUTezHXoBAaULMBXOEbwxMuyX/gBHiAYa/9f78pPLzI4UbQf12pA==" Nov 25 16:12:18 volumio go-librespot[14769]: time="2024-11-25T16:12:18+07:00" level=debug msg="completed keyexchange" Nov 25 16:12:19 volumio go-librespot[14769]: time="2024-11-25T16:12:19+07:00" level=debug msg="completed challenge" Nov 25 16:12:19 volumio go-librespot[14769]: time="2024-11-25T16:12:19+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 25 16:12:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 25 16:12:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 25 16:12:21 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:21 volumio volumio[1130]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 25 16:12:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 25 16:12:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 597. Nov 25 16:12:22 volumio systemd[1]: Stopped go-librespot Daemon. Nov 25 16:12:22 volumio systemd[1]: Started go-librespot Daemon. Nov 25 16:12:22 volumio go-librespot[14777]: Librespot-go daemon starting... Nov 25 16:12:22 volumio go-librespot[14777]: time="2024-11-25T16:12:22+07:00" level=info msg="generated new device id: dad21b0623ed4a6cdc2bf1453b9c93817156351d" Nov 25 16:12:22 volumio go-librespot[14777]: time="2024-11-25T16:12:22+07:00" level=debug msg="stored credentials found for 31vbebe5p5b3kovazuug5ryg5o5m" Nov 25 16:12:22 volumio go-librespot[14777]: time="2024-11-25T16:12:22+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]" Nov 25 16:12:22 volumio go-librespot[14777]: time="2024-11-25T16:12:22+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]" Nov 25 16:12:22 volumio go-librespot[14777]: time="2024-11-25T16:12:22+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]" Nov 25 16:12:22 volumio go-librespot[14777]: time="2024-11-25T16:12:22+07:00" level=debug msg="zeroconf server listening on port 46691" Nov 25 16:12:22 volumio go-librespot[14777]: time="2024-11-25T16:12:22+07:00" level=debug msg="obtained new client token: AAASpBACrNnKheNPhvj8FwKIVPjXF1NN7/m/bZmh/8wnZ6eb/jhdnfVw/hx6K+68h0p9MOsUL6HsIuX+sv/m6xuYPS/HSaS2CgJlv5Pn7en6HJ6ZD+oKgo0eHzu40gdLUFrWp04nxF8ECQjrn7UHvx98FuSEHLvZJEGWVqOWmRNV4gUg8rs/htdq7wVovYmYcVPFX5ngQdEePhSlQRnTAUCXJ5DTCjdhzhk536SaEve6Fa3W8MW3o58S2MZJiQ==" Nov 25 16:12:24 volumio volumio[1130]: info: Initializing connection to go-librespot Websocket Nov 25 16:12:24 volumio go-librespot[14777]: time="2024-11-25T16:12:24+07:00" level=debug msg="new websocket client" Nov 25 16:12:24 volumio volumio[1130]: info: Connection to go-librespot Websocket established Nov 25 16:12:27 volumio volumio[1130]: info: Getting Spotify volume Nov 25 16:12:27 volumio volumio[1130]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Nov 25 16:12:27 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:12:27 volumio volumio[1130]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 25 16:12:27 volumio volumio[1130]: SPOTIFY: SPOTIFY VOLUME 100 Nov 25 16:12:27 volumio volumio[1130]: SPOTIFY: VOLUMIO VOLUME 100 Nov 25 16:12:27 volumio volumio[1130]: SPOTIFY: DELTA VOLUME ENOUGH: false Nov 25 16:12:36 volumio ntpd[13359]: Soliciting pool server 2401:5f80:5001:1f::31f Nov 25 16:12:38 volumio ntpd[13359]: Soliciting pool server 115.165.161.155 Nov 25 16:12:39 volumio ntpd[13359]: Soliciting pool server 103.199.19.135 Nov 25 16:12:41 volumio ntpd[13359]: Soliciting pool server 103.184.124.23 Nov 25 16:13:16 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: youtube2 , handleBrowseUri Nov 25 16:13:16 volumio volumio[1130]: info: [youtube2-browse] browseUri: youtube2 Nov 25 16:13:16 volumio volumio[1130]: info: Preload queue cleared Nov 25 16:13:16 volumio volumio[1130]: info: Preload queue cleared Nov 25 16:13:16 volumio volumio[1130]: info: Preload queue cleared Nov 25 16:13:21 volumio kernel: tg3 0000:02:00.0 eth0: Link is down Nov 25 16:13:21 volumio dhcpcd[1649]: eth0: carrier lost Nov 25 16:13:21 volumio dhcpcd[1582]: eth0: carrier lost Nov 25 16:13:21 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:21 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:21 volumio avahi-daemon[816]: Withdrawing address record for 192.168.1.21 on eth0. Nov 25 16:13:21 volumio avahi-daemon[816]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.21. Nov 25 16:13:21 volumio avahi-daemon[816]: Interface eth0.IPv4 no longer relevant for mDNS. Nov 25 16:13:21 volumio volumio[1130]: info: Discovery: A device disappeared from network Nov 25 16:13:21 volumio volumio[1130]: info: Discovery: Device volumio disappeared from network Nov 25 16:13:21 volumio dhcpcd[1582]: eth0: deleting route to 192.168.1.0/24 Nov 25 16:13:21 volumio dhcpcd[1582]: eth0: deleting default route via 192.168.1.1 Nov 25 16:13:21 volumio dhcpcd[1649]: wlan0: adding default route Nov 25 16:13:21 volumio dhcpcd[1649]: eth0: deleting route to 192.168.1.0/24 Nov 25 16:13:21 volumio dhcpcd[1649]: eth0: deleting default route via 192.168.1.1 Nov 25 16:13:21 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:21 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:21 volumio dnsmasq[1173]: no servers found in /etc/resolv.conf, will retry Nov 25 16:13:22 volumio ifplugd(eth0)[1020]: Link beat lost. Nov 25 16:13:23 volumio ntpd[13359]: Deleting interface #3 eth0, 192.168.1.21#123, interface stats: received=0, sent=22, dropped=0, active_time=377 secs Nov 25 16:13:24 volumio kernel: tg3 0000:02:00.0 eth0: Link is up at 1000 Mbps, full duplex Nov 25 16:13:24 volumio kernel: tg3 0000:02:00.0 eth0: Flow control is on for TX and on for RX Nov 25 16:13:24 volumio kernel: tg3 0000:02:00.0 eth0: EEE is disabled Nov 25 16:13:24 volumio dhcpcd[1582]: eth0: carrier acquired Nov 25 16:13:24 volumio dhcpcd[1649]: eth0: carrier acquired Nov 25 16:13:24 volumio dhcpcd[1649]: eth0: IAID 54:06:92:81 Nov 25 16:13:24 volumio dhcpcd[1582]: eth0: IAID 54:06:92:81 Nov 25 16:13:24 volumio dhcpcd[1582]: eth0: soliciting an IPv6 router Nov 25 16:13:24 volumio ifplugd(eth0)[1020]: Link beat detected. Nov 25 16:13:24 volumio dhcpcd[1649]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:24 volumio dhcpcd[1649]: eth0: probing address 192.168.1.21/24 Nov 25 16:13:25 volumio dhcpcd[1582]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:25 volumio dhcpcd[1582]: eth0: probing address 192.168.1.21/24 Nov 25 16:13:25 volumio dhcpcd[1649]: eth0: soliciting an IPv6 router Nov 25 16:13:26 volumio kernel: tg3 0000:02:00.0 eth0: Link is down Nov 25 16:13:26 volumio dhcpcd[1649]: eth0: carrier lost Nov 25 16:13:26 volumio dhcpcd[1582]: eth0: carrier lost Nov 25 16:13:26 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:26 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:26 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:26 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:26 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:26 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:26 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:26 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:26 volumio ifplugd(eth0)[1020]: Link beat lost. Nov 25 16:13:29 volumio kernel: tg3 0000:02:00.0 eth0: Link is up at 1000 Mbps, full duplex Nov 25 16:13:29 volumio kernel: tg3 0000:02:00.0 eth0: Flow control is on for TX and on for RX Nov 25 16:13:29 volumio kernel: tg3 0000:02:00.0 eth0: EEE is disabled Nov 25 16:13:29 volumio dhcpcd[1582]: eth0: carrier acquired Nov 25 16:13:29 volumio dhcpcd[1649]: eth0: carrier acquired Nov 25 16:13:29 volumio dhcpcd[1582]: eth0: IAID 54:06:92:81 Nov 25 16:13:29 volumio dhcpcd[1649]: eth0: IAID 54:06:92:81 Nov 25 16:13:29 volumio dhcpcd[1582]: eth0: soliciting an IPv6 router Nov 25 16:13:30 volumio dhcpcd[1649]: eth0: soliciting an IPv6 router Nov 25 16:13:30 volumio ifplugd(eth0)[1020]: Link beat detected. Nov 25 16:13:30 volumio dhcpcd[1649]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:30 volumio dhcpcd[1649]: eth0: probing address 192.168.1.21/24 Nov 25 16:13:30 volumio dhcpcd[1582]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:30 volumio dhcpcd[1582]: eth0: probing address 192.168.1.21/24 Nov 25 16:13:35 volumio dhcpcd[1649]: eth0: leased 192.168.1.21 for 86400 seconds Nov 25 16:13:35 volumio dhcpcd[1649]: eth0: adding route to 192.168.1.0/24 Nov 25 16:13:35 volumio dhcpcd[1649]: eth0: adding default route via 192.168.1.1 Nov 25 16:13:35 volumio dhcpcd[1649]: wlan0: deleting default route Nov 25 16:13:35 volumio avahi-daemon[816]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.21. Nov 25 16:13:35 volumio avahi-daemon[816]: New relevant interface eth0.IPv4 for mDNS. Nov 25 16:13:35 volumio avahi-daemon[816]: Registering new address record for 192.168.1.21 on eth0.IPv4. Nov 25 16:13:35 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:35 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:35 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:35 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:35 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:35 volumio ntpd[13359]: ntpd exiting on signal 15 (Terminated) Nov 25 16:13:35 volumio systemd[1]: Stopping Network Time Service... Nov 25 16:13:35 volumio systemd[1]: ntp.service: Succeeded. Nov 25 16:13:35 volumio systemd[1]: Stopped Network Time Service. Nov 25 16:13:35 volumio systemd[1]: Starting Network Time Service... Nov 25 16:13:35 volumio ntpd[14985]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 25 16:13:35 volumio ntpd[14985]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Nov 25 16:13:35 volumio systemd[1]: Started Network Time Service. Nov 25 16:13:35 volumio ntpd[14991]: proto: precision = 0.105 usec (-23) Nov 25 16:13:35 volumio ntpd[14991]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Nov 25 16:13:35 volumio ntpd[14991]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Nov 25 16:13:35 volumio ntpd[14991]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 699 days ago Nov 25 16:13:35 volumio ntpd[14991]: Listen and drop on 0 v6wildcard [::]:123 Nov 25 16:13:35 volumio ntpd[14991]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 25 16:13:35 volumio ntpd[14991]: Listen normally on 2 lo 127.0.0.1:123 Nov 25 16:13:35 volumio ntpd[14991]: Listen normally on 3 eth0 192.168.1.21:123 Nov 25 16:13:35 volumio ntpd[14991]: Listen normally on 4 wlan0 192.168.211.1:123 Nov 25 16:13:35 volumio ntpd[14991]: Listen normally on 5 wlan0 169.254.220.179:123 Nov 25 16:13:35 volumio ntpd[14991]: Listening on routing socket on fd #22 for interface updates Nov 25 16:13:35 volumio ntpd[14991]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:35 volumio ntpd[14991]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:35 volumio dhcpcd[1582]: eth0: leased 192.168.1.21 for 86400 seconds Nov 25 16:13:35 volumio dhcpcd[1582]: eth0: adding route to 192.168.1.0/24 Nov 25 16:13:35 volumio dhcpcd[1582]: eth0: adding default route via 192.168.1.1 Nov 25 16:13:35 volumio ntpd[14991]: ntpd exiting on signal 15 (Terminated) Nov 25 16:13:35 volumio systemd[1]: Stopping Network Time Service... Nov 25 16:13:35 volumio systemd[1]: ntp.service: Succeeded. Nov 25 16:13:35 volumio systemd[1]: Stopped Network Time Service. Nov 25 16:13:35 volumio systemd[1]: Starting Network Time Service... Nov 25 16:13:35 volumio ntpd[15026]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 25 16:13:35 volumio ntpd[15026]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Nov 25 16:13:35 volumio systemd[1]: Started Network Time Service. Nov 25 16:13:35 volumio ntpd[15032]: proto: precision = 0.062 usec (-24) Nov 25 16:13:35 volumio ntpd[15032]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Nov 25 16:13:35 volumio ntpd[15032]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Nov 25 16:13:35 volumio ntpd[15032]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 699 days ago Nov 25 16:13:35 volumio ntpd[15032]: Listen and drop on 0 v6wildcard [::]:123 Nov 25 16:13:35 volumio ntpd[15032]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 25 16:13:35 volumio ntpd[15032]: Listen normally on 2 lo 127.0.0.1:123 Nov 25 16:13:35 volumio ntpd[15032]: Listen normally on 3 eth0 192.168.1.21:123 Nov 25 16:13:35 volumio ntpd[15032]: Listen normally on 4 wlan0 192.168.211.1:123 Nov 25 16:13:35 volumio ntpd[15032]: Listen normally on 5 wlan0 169.254.220.179:123 Nov 25 16:13:35 volumio ntpd[15032]: Listening on routing socket on fd #22 for interface updates Nov 25 16:13:35 volumio ntpd[15032]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:35 volumio ntpd[15032]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:36 volumio volumio[1130]: info: Discovery: adding 16f8dc13-fbfd-4832-a3a9-cd7c2c653ae6 Nov 25 16:13:36 volumio volumio[1130]: info: Discovery: Found device Volumio Nov 25 16:13:36 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:13:36 volumio ntpd[15032]: Soliciting pool server 103.130.217.41 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 10 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 11 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 12 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 13 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 14 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 15 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 16 Nov 25 16:13:37 volumio ntpd[15032]: Soliciting pool server 103.199.19.135 Nov 25 16:13:37 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 17 Nov 25 16:13:38 volumio kernel: tg3 0000:02:00.0 eth0: Link is down Nov 25 16:13:38 volumio dhcpcd[1582]: eth0: carrier lost Nov 25 16:13:38 volumio dhcpcd[1649]: eth0: carrier lost Nov 25 16:13:38 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:38 volumio avahi-daemon[816]: Withdrawing address record for 192.168.1.21 on eth0. Nov 25 16:13:38 volumio avahi-daemon[816]: Leaving mDNS multicast group on interface eth0.IPv4 with address 192.168.1.21. Nov 25 16:13:38 volumio avahi-daemon[816]: Interface eth0.IPv4 no longer relevant for mDNS. Nov 25 16:13:38 volumio volumio[1130]: info: Discovery: A device disappeared from network Nov 25 16:13:38 volumio volumio[1130]: info: Discovery: Device volumio disappeared from network Nov 25 16:13:38 volumio dhcpcd[1582]: eth0: deleting route to 192.168.1.0/24 Nov 25 16:13:38 volumio dhcpcd[1582]: eth0: deleting default route via 192.168.1.1 Nov 25 16:13:38 volumio dhcpcd[1649]: wlan0: adding default route Nov 25 16:13:38 volumio dhcpcd[1649]: eth0: deleting route to 192.168.1.0/24 Nov 25 16:13:38 volumio dhcpcd[1649]: eth0: deleting default route via 192.168.1.1 Nov 25 16:13:38 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:38 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:38 volumio dnsmasq[1173]: no servers found in /etc/resolv.conf, will retry Nov 25 16:13:39 volumio ifplugd(eth0)[1020]: Link beat lost. Nov 25 16:13:40 volumio ntpd[15032]: Deleting interface #3 eth0, 192.168.1.21#123, interface stats: received=0, sent=2, dropped=0, active_time=5 secs Nov 25 16:13:41 volumio kernel: tg3 0000:02:00.0 eth0: Link is up at 1000 Mbps, full duplex Nov 25 16:13:41 volumio kernel: tg3 0000:02:00.0 eth0: Flow control is on for TX and on for RX Nov 25 16:13:41 volumio kernel: tg3 0000:02:00.0 eth0: EEE is disabled Nov 25 16:13:41 volumio dhcpcd[1582]: eth0: carrier acquired Nov 25 16:13:41 volumio dhcpcd[1649]: eth0: carrier acquired Nov 25 16:13:41 volumio dhcpcd[1649]: eth0: IAID 54:06:92:81 Nov 25 16:13:41 volumio dhcpcd[1582]: eth0: IAID 54:06:92:81 Nov 25 16:13:42 volumio dhcpcd[1649]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:42 volumio dhcpcd[1649]: eth0: soliciting an IPv6 router Nov 25 16:13:42 volumio dhcpcd[1582]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:42 volumio ifplugd(eth0)[1020]: Link beat detected. Nov 25 16:13:42 volumio dhcpcd[1582]: eth0: soliciting an IPv6 router Nov 25 16:13:43 volumio kernel: tg3 0000:02:00.0 eth0: Link is down Nov 25 16:13:43 volumio dhcpcd[1649]: eth0: carrier lost Nov 25 16:13:43 volumio dhcpcd[1582]: eth0: carrier lost Nov 25 16:13:43 volumio ifplugd(eth0)[1020]: Link beat lost. Nov 25 16:13:45 volumio kernel: tg3 0000:02:00.0 eth0: Link is up at 1000 Mbps, full duplex Nov 25 16:13:45 volumio kernel: tg3 0000:02:00.0 eth0: Flow control is on for TX and on for RX Nov 25 16:13:45 volumio kernel: tg3 0000:02:00.0 eth0: EEE is disabled Nov 25 16:13:45 volumio dhcpcd[1649]: eth0: carrier acquired Nov 25 16:13:45 volumio dhcpcd[1582]: eth0: carrier acquired Nov 25 16:13:45 volumio dhcpcd[1582]: eth0: IAID 54:06:92:81 Nov 25 16:13:45 volumio dhcpcd[1649]: eth0: IAID 54:06:92:81 Nov 25 16:13:46 volumio dhcpcd[1649]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:46 volumio dhcpcd[1649]: eth0: probing address 192.168.1.21/24 Nov 25 16:13:46 volumio ifplugd(eth0)[1020]: Link beat detected. Nov 25 16:13:46 volumio dhcpcd[1582]: eth0: soliciting an IPv6 router Nov 25 16:13:46 volumio dhcpcd[1582]: eth0: rebinding lease of 192.168.1.21 Nov 25 16:13:46 volumio dhcpcd[1582]: eth0: probing address 192.168.1.21/24 Nov 25 16:13:46 volumio dhcpcd[1649]: eth0: soliciting an IPv6 router Nov 25 16:13:50 volumio dhcpcd[1649]: eth0: leased 192.168.1.21 for 86400 seconds Nov 25 16:13:50 volumio dhcpcd[1649]: eth0: adding route to 192.168.1.0/24 Nov 25 16:13:50 volumio dhcpcd[1649]: eth0: adding default route via 192.168.1.1 Nov 25 16:13:50 volumio dhcpcd[1649]: wlan0: deleting default route Nov 25 16:13:50 volumio avahi-daemon[816]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.21. Nov 25 16:13:50 volumio avahi-daemon[816]: New relevant interface eth0.IPv4 for mDNS. Nov 25 16:13:50 volumio avahi-daemon[816]: Registering new address record for 192.168.1.21 on eth0.IPv4. Nov 25 16:13:50 volumio dnsmasq[1173]: reading /etc/resolv.conf Nov 25 16:13:50 volumio dnsmasq[1173]: using nameserver 123.23.23.23#53 Nov 25 16:13:50 volumio dnsmasq[1173]: using nameserver 123.26.26.26#53 Nov 25 16:13:50 volumio dnsmasq[1173]: using nameserver 208.67.222.222#53 Nov 25 16:13:50 volumio dnsmasq[1173]: using nameserver 208.67.220.220#53 Nov 25 16:13:50 volumio ntpd[15032]: ntpd exiting on signal 15 (Terminated) Nov 25 16:13:50 volumio systemd[1]: Stopping Network Time Service... Nov 25 16:13:50 volumio systemd[1]: ntp.service: Succeeded. Nov 25 16:13:50 volumio systemd[1]: Stopped Network Time Service. Nov 25 16:13:50 volumio systemd[1]: Starting Network Time Service... Nov 25 16:13:50 volumio ntpd[15168]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 25 16:13:50 volumio ntpd[15168]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Nov 25 16:13:50 volumio systemd[1]: Started Network Time Service. Nov 25 16:13:50 volumio ntpd[15174]: proto: precision = 0.061 usec (-24) Nov 25 16:13:50 volumio ntpd[15174]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Nov 25 16:13:50 volumio ntpd[15174]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Nov 25 16:13:50 volumio ntpd[15174]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 699 days ago Nov 25 16:13:50 volumio ntpd[15174]: Listen and drop on 0 v6wildcard [::]:123 Nov 25 16:13:50 volumio ntpd[15174]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 25 16:13:50 volumio ntpd[15174]: Listen normally on 2 lo 127.0.0.1:123 Nov 25 16:13:50 volumio ntpd[15174]: Listen normally on 3 eth0 192.168.1.21:123 Nov 25 16:13:50 volumio ntpd[15174]: Listen normally on 4 wlan0 192.168.211.1:123 Nov 25 16:13:50 volumio ntpd[15174]: Listen normally on 5 wlan0 169.254.220.179:123 Nov 25 16:13:50 volumio ntpd[15174]: Listening on routing socket on fd #22 for interface updates Nov 25 16:13:50 volumio ntpd[15174]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:50 volumio ntpd[15174]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:51 volumio volumio[1130]: info: Discovery: adding 16f8dc13-fbfd-4832-a3a9-cd7c2c653ae6 Nov 25 16:13:51 volumio volumio[1130]: info: Discovery: Found device Volumio Nov 25 16:13:51 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:13:51 volumio ntpd[15174]: Soliciting pool server 27.71.27.209 Nov 25 16:13:52 volumio dhcpcd[1582]: eth0: leased 192.168.1.21 for 86400 seconds Nov 25 16:13:52 volumio dhcpcd[1582]: eth0: adding route to 192.168.1.0/24 Nov 25 16:13:52 volumio dhcpcd[1582]: eth0: adding default route via 192.168.1.1 Nov 25 16:13:52 volumio ntpd[15174]: ntpd exiting on signal 15 (Terminated) Nov 25 16:13:52 volumio systemd[1]: Stopping Network Time Service... Nov 25 16:13:52 volumio systemd[1]: ntp.service: Succeeded. Nov 25 16:13:52 volumio systemd[1]: Stopped Network Time Service. Nov 25 16:13:52 volumio systemd[1]: Starting Network Time Service... Nov 25 16:13:52 volumio ntpd[15209]: ntpd 4.2.8p12@1.3728-o (1): Starting Nov 25 16:13:52 volumio ntpd[15209]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 104:103 Nov 25 16:13:52 volumio systemd[1]: Started Network Time Service. Nov 25 16:13:52 volumio ntpd[15215]: proto: precision = 0.109 usec (-23) Nov 25 16:13:52 volumio ntpd[15215]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Nov 25 16:13:52 volumio ntpd[15215]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2022-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Nov 25 16:13:52 volumio ntpd[15215]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 699 days ago Nov 25 16:13:52 volumio ntpd[15215]: Listen and drop on 0 v6wildcard [::]:123 Nov 25 16:13:52 volumio ntpd[15215]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Nov 25 16:13:52 volumio ntpd[15215]: Listen normally on 2 lo 127.0.0.1:123 Nov 25 16:13:52 volumio ntpd[15215]: Listen normally on 3 eth0 192.168.1.21:123 Nov 25 16:13:52 volumio ntpd[15215]: Listen normally on 4 wlan0 192.168.211.1:123 Nov 25 16:13:52 volumio ntpd[15215]: Listen normally on 5 wlan0 169.254.220.179:123 Nov 25 16:13:52 volumio ntpd[15215]: Listening on routing socket on fd #22 for interface updates Nov 25 16:13:52 volumio ntpd[15215]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:52 volumio ntpd[15215]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Nov 25 16:13:52 volumio volumio[1130]: verbose: New Socket.io Connection to 192.168.1.21 from 192.168.1.3 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_7_10 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 17 Nov 25 16:13:52 volumio volumiossh-tunnel[2187]: packet_write_wait: Connection to 128.199.166.162 port 2222: Broken pipe Nov 25 16:13:52 volumio autossh[2188]: ssh exited with error status 255; restarting ssh Nov 25 16:13:52 volumio autossh[2188]: starting ssh (count 2) Nov 25 16:13:52 volumio autossh[2188]: ssh child pid is 15261 Nov 25 16:13:52 volumio volumio[1130]: info: Received Get System Info Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 25 16:13:52 volumio volumio[1130]: info: Discovery: Getting this device information Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::volumioGetVisibleSources Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::volumioGetQueue Nov 25 16:13:52 volumio volumio[1130]: info: CoreStateMachine::getQueue Nov 25 16:13:52 volumio volumio[1130]: info: CorePlayQueue::getQueue Nov 25 16:13:52 volumio volumio[1130]: info: Listing playlists Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 25 16:13:52 volumio volumio[1130]: info: Received Get System Info Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 25 16:13:52 volumio volumio[1130]: info: Discovery: Getting this device information Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 25 16:13:52 volumio volumio[1130]: info: CoreCommandRouter::volumioGetState Nov 25 16:13:53 volumio volumiossh-tunnel[2187]: Warning: Permanently added '[as1.myvolumio.org]:2222,[128.199.166.162]:2222' (RSA) to the list of known hosts. Nov 25 16:13:53 volumio ntpd[15215]: Soliciting pool server 27.71.27.209 Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:53 volumio volumio[1130]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 25 16:13:54 volumio ntpd[15215]: Soliciting pool server 103.199.19.135 Nov 25 16:13:55 volumio ntpd[15215]: Soliciting pool server 103.184.124.23 Nov 25 16:13:56 volumio ntpd[15215]: Soliciting pool server 103.130.217.41 Nov 25 16:13:59 volumio volumio[1130]: info: CoreCommandRouter::executeOnPlugin: metavolumio , superSearch Nov 25 16:13:59 volumio volumio[1130]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 25 16:13:59 volumio volumio[1130]: TypeError: Cannot read property 'then' of undefined Nov 25 16:13:59 volumio volumio[1130]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:498:20) Nov 25 16:13:59 volumio volumio[1130]: at Socket.emit (events.js:400:28) Nov 25 16:13:59 volumio volumio[1130]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 25 16:13:59 volumio volumio[1130]: at processTicksAndRejections (internal/process/task_queues.js:77:11) Nov 25 16:13:59 volumio volumio[1130]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 25 16:13:59 volumio sudo[15277]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-25 16:12 Nov 25 16:13:59 volumio sudo[15277]: 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="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"