-- Logs begin at Mon 2024-09-09 11:42:12 CST, end at Mon 2024-09-09 11:46:21 CST. -- Sep 09 11:45:00 volumio go-librespot[1497]: time="2024-09-09T11:45:00+08:00" level=debug msg="completed challenge" Sep 09 11:45:00 volumio go-librespot[1497]: time="2024-09-09T11:45:00+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:00 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:00 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:00 volumio volumio[921]: info: Listing playlists Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:00 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:00 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:00 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:00 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:00 volumio volumio[921]: info: Listing playlists Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:00 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:00 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:00 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:00 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:00 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:02 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:02 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:02 volumio volumio[921]: info: Listing playlists Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:02 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:02 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:02 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:02 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:02 volumio volumio[921]: info: Listing playlists Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:02 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:02 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:02 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:02 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Sep 09 11:45:03 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:03 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:03 volumio go-librespot[1505]: Librespot-go daemon starting... Sep 09 11:45:03 volumio go-librespot[1505]: time="2024-09-09T11:45:03+08:00" level=info msg="generated new device id: 662eb626e01e1b2c13b2d3edf59b69321414ab30" Sep 09 11:45:03 volumio go-librespot[1505]: time="2024-09-09T11:45:03+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:03 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:03 volumio go-librespot[1505]: time="2024-09-09T11:45:03+08:00" level=debug msg="new websocket client" Sep 09 11:45:03 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:45:04 volumio go-librespot[1505]: time="2024-09-09T11:45:04+08: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]" Sep 09 11:45:04 volumio go-librespot[1505]: time="2024-09-09T11:45:04+08: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]" Sep 09 11:45:04 volumio go-librespot[1505]: time="2024-09-09T11:45:04+08: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]" Sep 09 11:45:04 volumio go-librespot[1505]: time="2024-09-09T11:45:04+08:00" level=debug msg="zeroconf server listening on port 33769" Sep 09 11:45:04 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:04 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:04 volumio volumio[921]: info: Listing playlists Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:04 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:04 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:04 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:04 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:04 volumio volumio[921]: info: Listing playlists Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:04 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:04 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:04 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:04 volumio go-librespot[1505]: time="2024-09-09T11:45:04+08:00" level=debug msg="obtained new client token: AAA1y6BqgIZ7ocb9M9o+aMGDwl0fqmv1S63I/B4pJstF2gJ/rs4oDfqpRBH267WvAP8P+Sg7TIhor2xgkh0w4ELQlnLaZ21nc/PXCm6ek28DyB9qVfhiQtfLOPxOnAon5XWRUG4YwRhOw+kuxi5CXwVP7GWWJFgp3cntx4hwfyD81ngG0+LBAjMIRnDBlRcsnA1b3u2F28XF3mmcHb3wWQKuCwoRf5H29bj4GpE1c8ZxhKRKHM4W2f8aiAIe" Sep 09 11:45:04 volumio go-librespot[1505]: time="2024-09-09T11:45:04+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:05 volumio go-librespot[1505]: time="2024-09-09T11:45:05+08:00" level=debug msg="completed challenge" Sep 09 11:45:05 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:05 volumio go-librespot[1505]: time="2024-09-09T11:45:05+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:05 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:05 volumio volumio[921]: info: Listing playlists Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:05 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:05 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:05 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:05 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:05 volumio volumio[921]: info: Listing playlists Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:05 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:05 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:05 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:05 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:45:06 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:06 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:06 volumio volumio[921]: info: Listing playlists Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:06 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:06 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:06 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:06 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:06 volumio volumio[921]: info: Listing playlists Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:06 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:06 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:06 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:06 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:06 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:45:06 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:06 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:45:06 volumio volumio[921]: (node:921) 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: 9) Sep 09 11:45:06 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:07 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:07 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:08 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:08 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:08 volumio volumio[921]: info: Listing playlists Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:08 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:08 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:08 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:08 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:08 volumio volumio[921]: info: Listing playlists Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:08 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:08 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:08 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:08 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:08 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:08 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Sep 09 11:45:08 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:08 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:08 volumio go-librespot[1516]: Librespot-go daemon starting... Sep 09 11:45:08 volumio go-librespot[1516]: time="2024-09-09T11:45:08+08:00" level=info msg="generated new device id: e618481cd226cc5189eb3e809894de59f428afc8" Sep 09 11:45:08 volumio go-librespot[1516]: time="2024-09-09T11:45:08+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:09 volumio go-librespot[1516]: time="2024-09-09T11:45:09+08: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]" Sep 09 11:45:09 volumio go-librespot[1516]: time="2024-09-09T11:45:09+08: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]" Sep 09 11:45:09 volumio go-librespot[1516]: time="2024-09-09T11:45:09+08: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]" Sep 09 11:45:09 volumio go-librespot[1516]: time="2024-09-09T11:45:09+08:00" level=debug msg="zeroconf server listening on port 46345" Sep 09 11:45:09 volumio go-librespot[1516]: time="2024-09-09T11:45:09+08:00" level=debug msg="obtained new client token: AACAPDe0npIcZKCAZ4tu3NrQKNbPukpq/9ySCX22F5EyR7WvJFL8NNWFwWh5mMNVo9nHEJyv/SvyWf8H3gzp0ih/YmrCQz6bfiSUGWSxQuWsK9zg7QLfBiJAANhUF7g6g+KwyH1Q5IXrl+Pi8r1n/VzWwezYaIQLkzIHh+7gkfw9jT5c0rhFgh2+NaKjthIw9UqhHsBgVh+w5DQ+jvWRoAZ0gAju3lfLV27dkLLPRPnVPE+HBBnm6xL/hwCf" Sep 09 11:45:09 volumio go-librespot[1516]: time="2024-09-09T11:45:09+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:10 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:10 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:10 volumio go-librespot[1516]: time="2024-09-09T11:45:10+08:00" level=debug msg="completed challenge" Sep 09 11:45:10 volumio volumio[921]: info: Listing playlists Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:10 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:10 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:10 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:10 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:10 volumio volumio[921]: info: Listing playlists Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:10 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:10 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:10 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:10 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:10 volumio go-librespot[1516]: time="2024-09-09T11:45:10+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:11 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:11 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:12 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:12 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:12 volumio volumio[921]: info: Listing playlists Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:12 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:12 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:12 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:12 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:12 volumio volumio[921]: info: Listing playlists Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:12 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:12 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:12 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:12 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:13 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:13 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:13 volumio volumio[921]: info: Listing playlists Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:13 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:13 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:13 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:13 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:13 volumio volumio[921]: info: Listing playlists Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:13 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:13 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:13 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Sep 09 11:45:13 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:13 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:13 volumio go-librespot[1524]: Librespot-go daemon starting... Sep 09 11:45:13 volumio go-librespot[1524]: time="2024-09-09T11:45:13+08:00" level=info msg="generated new device id: d411a16ca85ff9f8d3dfdae3571f2ae96441dec6" Sep 09 11:45:13 volumio go-librespot[1524]: time="2024-09-09T11:45:13+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:14 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:14 volumio go-librespot[1524]: time="2024-09-09T11:45:14+08:00" level=debug msg="new websocket client" Sep 09 11:45:14 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:45:14 volumio go-librespot[1524]: time="2024-09-09T11:45:14+08: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]" Sep 09 11:45:14 volumio go-librespot[1524]: time="2024-09-09T11:45:14+08: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]" Sep 09 11:45:14 volumio go-librespot[1524]: time="2024-09-09T11:45:14+08: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]" Sep 09 11:45:14 volumio go-librespot[1524]: time="2024-09-09T11:45:14+08:00" level=debug msg="zeroconf server listening on port 33937" Sep 09 11:45:15 volumio go-librespot[1524]: time="2024-09-09T11:45:15+08:00" level=debug msg="obtained new client token: AABHAaFL27tqNHXRa+KuubsXCgpnKFn/RQbIkOCWxPzNXmdPmuWJrTwR5+vWY68VxCmaIniZzyb/6K3p1CVrMg5UhijH+IN98KrsL+qyDqFa1vMO04fftX77tHF+SUGdj/dah9cNT4+ctKN9EsXB/8vN166Smh7UI6ro2qqgwUnvTit6IZsBUnvxXjA8v+dHnZH8C6VnVjVf29hLJb3Wsa9HNpF1tAhOeWSK3iATRfblWQgwfUgigz+oOYyP" Sep 09 11:45:15 volumio go-librespot[1524]: time="2024-09-09T11:45:15+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:15 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:15 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:15 volumio volumio[921]: info: Listing playlists Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:15 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:15 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:15 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:15 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:15 volumio volumio[921]: info: Listing playlists Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:15 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:15 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:15 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:15 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:15 volumio go-librespot[1524]: time="2024-09-09T11:45:15+08:00" level=debug msg="completed challenge" Sep 09 11:45:15 volumio go-librespot[1524]: time="2024-09-09T11:45:15+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:15 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:45:17 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:17 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:17 volumio volumio[921]: info: Listing playlists Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:17 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:17 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:17 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:17 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:17 volumio volumio[921]: info: Listing playlists Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:17 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:17 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:17 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:17 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:45:17 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:17 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:45:17 volumio volumio[921]: (node:921) 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: 10) Sep 09 11:45:17 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:17 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:17 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:18 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:18 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:18 volumio volumio[921]: info: Listing playlists Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:18 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:18 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:18 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:18 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:18 volumio volumio[921]: info: Listing playlists Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:18 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:18 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:18 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:18 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:18 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Sep 09 11:45:18 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:19 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:19 volumio go-librespot[1534]: Librespot-go daemon starting... Sep 09 11:45:19 volumio go-librespot[1534]: time="2024-09-09T11:45:19+08:00" level=info msg="generated new device id: 8b88c0fb0b7d27abd3391c01085a9f473a1c5b5d" Sep 09 11:45:19 volumio go-librespot[1534]: time="2024-09-09T11:45:19+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:19 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:19 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:19 volumio volumio[921]: info: Listing playlists Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:19 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:19 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:19 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:19 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:19 volumio volumio[921]: info: Listing playlists Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:19 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:19 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:19 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:19 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:19 volumio go-librespot[1534]: time="2024-09-09T11:45:19+08: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]" Sep 09 11:45:19 volumio go-librespot[1534]: time="2024-09-09T11:45:19+08: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]" Sep 09 11:45:19 volumio go-librespot[1534]: time="2024-09-09T11:45:19+08: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]" Sep 09 11:45:19 volumio go-librespot[1534]: time="2024-09-09T11:45:19+08:00" level=debug msg="zeroconf server listening on port 39545" Sep 09 11:45:20 volumio go-librespot[1534]: time="2024-09-09T11:45:20+08:00" level=debug msg="obtained new client token: AADXG1RNZtkJHaUCKW6BVDUdEE3ymJoLmFeG/tP/Q+nbDs4bdMSpIQjVsEmHNO0yQswKFZUOQ6x8cmQdR8DCLjxezWOdqWQjl2qCuFF2hLxsPzJ940VC+tR5x1Y/X/UBOhvD6tLsEbeOinOwvIbUUIHt+FPZOX3hI0F5TaF/NhU+7Unf2CWmS8LXJG1k1/IxYhZ59Koyyj3Ioi/noVG8C0qxNtHEeM44FTI9NWe0P1PtIvB3ZXX/pj1Muw==" Sep 09 11:45:20 volumio go-librespot[1534]: time="2024-09-09T11:45:20+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:20 volumio go-librespot[1534]: time="2024-09-09T11:45:20+08:00" level=debug msg="completed challenge" Sep 09 11:45:21 volumio go-librespot[1534]: time="2024-09-09T11:45:21+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:21 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:21 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:21 volumio volumio[921]: info: Listing playlists Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:21 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:21 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:21 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:21 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:21 volumio volumio[921]: info: Listing playlists Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:21 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:21 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:21 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:21 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:21 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:21 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:23 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:23 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:23 volumio volumio[921]: info: Listing playlists Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:23 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:23 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:23 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:23 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:23 volumio volumio[921]: info: Listing playlists Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:23 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:23 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:23 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:23 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:24 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Sep 09 11:45:24 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:24 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:24 volumio go-librespot[1542]: Librespot-go daemon starting... Sep 09 11:45:24 volumio go-librespot[1542]: time="2024-09-09T11:45:24+08:00" level=info msg="generated new device id: 3e19e5148c92100dc100e0bd003b8cdb34096db6" Sep 09 11:45:24 volumio go-librespot[1542]: time="2024-09-09T11:45:24+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:24 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:24 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:24 volumio volumio[921]: info: Listing playlists Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:24 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:24 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:24 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:24 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:24 volumio volumio[921]: info: Listing playlists Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:24 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:24 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:24 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:24 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:24 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:24 volumio go-librespot[1542]: time="2024-09-09T11:45:24+08:00" level=debug msg="new websocket client" Sep 09 11:45:24 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:45:24 volumio go-librespot[1542]: time="2024-09-09T11:45:24+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 09 11:45:24 volumio go-librespot[1542]: time="2024-09-09T11:45:24+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 09 11:45:24 volumio go-librespot[1542]: time="2024-09-09T11:45:24+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 09 11:45:25 volumio go-librespot[1542]: time="2024-09-09T11:45:25+08:00" level=debug msg="zeroconf server listening on port 46489" Sep 09 11:45:25 volumio go-librespot[1542]: time="2024-09-09T11:45:25+08:00" level=debug msg="obtained new client token: AABTnovx6qFUlMX7PPzUVjiiFvNawLUZbVS49zLwN+RJYu86yyBcpOzSi+/Pv8XZcxfyI9t4qPp23uGyw87v3jdldqenA0Y7ILlIfmwpB8PzYxQXg8ikDwCKadSDmY1WnlTzGkyg1bnqYKnnk49Q4La6qxNdyJqkcR0iX101yGh/9b+OmLtd/PCd7sKhwyqy3OkFM1iGVCAeNYxxSaCW3gQ6dkfbkMz0eK0GeC+FBJlgftGDyzFQA72w3wW7" Sep 09 11:45:25 volumio go-librespot[1542]: time="2024-09-09T11:45:25+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:26 volumio go-librespot[1542]: time="2024-09-09T11:45:26+08:00" level=debug msg="completed challenge" Sep 09 11:45:26 volumio go-librespot[1542]: time="2024-09-09T11:45:26+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:26 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:45:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:26 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:26 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:26 volumio volumio[921]: info: Listing playlists Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:26 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:26 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:26 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:26 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:26 volumio volumio[921]: info: Listing playlists Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:26 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:26 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:26 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:26 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:27 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:45:27 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:27 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:45:27 volumio volumio[921]: (node:921) 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: 11) Sep 09 11:45:27 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:27 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:27 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:28 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:28 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:28 volumio volumio[921]: info: Listing playlists Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:28 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:28 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:28 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:28 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:28 volumio volumio[921]: info: Listing playlists Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:28 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:28 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:28 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:28 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:29 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:29 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:29 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Sep 09 11:45:29 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:29 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:29 volumio go-librespot[1550]: Librespot-go daemon starting... Sep 09 11:45:29 volumio go-librespot[1550]: time="2024-09-09T11:45:29+08:00" level=info msg="generated new device id: c8d2045cd59a372cb47d51f0e2b19b4b7d3bf19e" Sep 09 11:45:29 volumio go-librespot[1550]: time="2024-09-09T11:45:29+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:30 volumio go-librespot[1550]: time="2024-09-09T11:45:30+08: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]" Sep 09 11:45:30 volumio go-librespot[1550]: time="2024-09-09T11:45:30+08: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]" Sep 09 11:45:30 volumio go-librespot[1550]: time="2024-09-09T11:45:30+08: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]" Sep 09 11:45:30 volumio go-librespot[1550]: time="2024-09-09T11:45:30+08:00" level=debug msg="zeroconf server listening on port 35425" Sep 09 11:45:30 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:30 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:30 volumio volumio[921]: info: Listing playlists Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:30 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:30 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:30 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:30 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:30 volumio volumio[921]: info: Listing playlists Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:30 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:30 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:30 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:30 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:30 volumio go-librespot[1550]: time="2024-09-09T11:45:30+08:00" level=debug msg="obtained new client token: AABG31dAaZgE8bM6jKnYLykJ95kzT8YulwxSwQmA0K61T+9DLw9qAwxlQ8JpclEh++3McAdghumjyloR0WVQ2MOJZds/gAxdhkMqdmIOxDTceX+iEJEHJBLSg8cQqJZGCWLtGwblyhdiMfLwQJIk27gIyiFpEkafqB/3LnPwwEjf6kZ5za0Mk3QWN3sWa4kO5CLH52G2Ik/ILj75yXEgiaoXgV1CGiqTv3o+sCr0Xv9yMl70IJ1fprHboZ2U" Sep 09 11:45:30 volumio go-librespot[1550]: time="2024-09-09T11:45:30+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:31 volumio go-librespot[1550]: time="2024-09-09T11:45:31+08:00" level=debug msg="completed challenge" Sep 09 11:45:31 volumio go-librespot[1550]: time="2024-09-09T11:45:31+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:32 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:32 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:32 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:32 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:32 volumio volumio[921]: info: Listing playlists Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:32 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:32 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:32 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:32 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:32 volumio volumio[921]: info: Listing playlists Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:32 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:32 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:32 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:32 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:33 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:33 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:33 volumio volumio[921]: info: Listing playlists Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:33 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:33 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:33 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:33 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:33 volumio volumio[921]: info: Listing playlists Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:33 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:33 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:33 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:33 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:34 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:34 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:34 volumio volumio[921]: info: Listing playlists Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:34 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:34 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:34 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:34 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:34 volumio volumio[921]: info: Listing playlists Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:34 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:34 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:34 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:34 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Sep 09 11:45:34 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:34 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:34 volumio go-librespot[1558]: Librespot-go daemon starting... Sep 09 11:45:34 volumio go-librespot[1558]: time="2024-09-09T11:45:34+08:00" level=info msg="generated new device id: 6703e7f6ce91ead79cff2449f89d9dba96257ec3" Sep 09 11:45:34 volumio go-librespot[1558]: time="2024-09-09T11:45:34+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:35 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:35 volumio go-librespot[1558]: time="2024-09-09T11:45:35+08: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]" Sep 09 11:45:35 volumio go-librespot[1558]: time="2024-09-09T11:45:35+08: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]" Sep 09 11:45:35 volumio go-librespot[1558]: time="2024-09-09T11:45:35+08: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]" Sep 09 11:45:35 volumio go-librespot[1558]: time="2024-09-09T11:45:35+08:00" level=debug msg="new websocket client" Sep 09 11:45:35 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:45:35 volumio go-librespot[1558]: time="2024-09-09T11:45:35+08:00" level=debug msg="zeroconf server listening on port 38023" Sep 09 11:45:35 volumio go-librespot[1558]: time="2024-09-09T11:45:35+08:00" level=debug msg="obtained new client token: AABzKKjjBMrlHYDwU1Z2CvJeTVgT2eeoTLweKcMYO5YKICowCLLodyervNM4eAE2TEHi327xJSVp5mpm+ygicBJS3rNcFjq+awKUsfnMXlPwrXdv01KrZJ59UNBsu7z6C3tgpa9d7ao/kfoibUXYEtWdBL3OmFpCvVdxbW+T9X7bej3amfH7JtsvPJFnPL1rIn2dr3P/kE3G4G1rJBVfgqwy/Tu4Ftnd3lKbOImgyRfjkG6dlJRASe2JzK8u" Sep 09 11:45:35 volumio go-librespot[1558]: time="2024-09-09T11:45:35+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:36 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:36 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:36 volumio volumio[921]: info: Listing playlists Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:36 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:36 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:36 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:36 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:36 volumio volumio[921]: info: Listing playlists Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:36 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:36 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:36 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:36 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:36 volumio go-librespot[1558]: time="2024-09-09T11:45:36+08:00" level=debug msg="completed challenge" Sep 09 11:45:36 volumio go-librespot[1558]: time="2024-09-09T11:45:36+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:36 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:36 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:36 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:45:37 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:37 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:37 volumio volumio[921]: info: Listing playlists Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:37 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:37 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:37 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:37 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:37 volumio volumio[921]: info: Listing playlists Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:37 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:37 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:37 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:37 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:38 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:45:38 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:38 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:45:38 volumio volumio[921]: (node:921) 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: 12) Sep 09 11:45:38 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:38 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:38 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:39 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:39 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:39 volumio volumio[921]: info: Listing playlists Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:39 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:39 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:39 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:39 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:39 volumio volumio[921]: info: Listing playlists Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:39 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:39 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:39 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:39 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:39 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:39 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:39 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:39 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Sep 09 11:45:39 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:39 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:39 volumio go-librespot[1568]: Librespot-go daemon starting... Sep 09 11:45:39 volumio go-librespot[1568]: time="2024-09-09T11:45:39+08:00" level=info msg="generated new device id: 914ef00fc21d81a561bb46c5f3cfa8075500322c" Sep 09 11:45:39 volumio go-librespot[1568]: time="2024-09-09T11:45:39+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:40 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:40 volumio volumio[921]: error: [now-playing] API endpoint weather/fetchInfo returned error: Error: Could not access weather service: missing geographic coordinates. Sep 09 11:45:40 volumio volumio[921]: at WeatherAPI.fetchInfo (/data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:106:19) Sep 09 11:45:40 volumio volumio[921]: at Object.api (/data/plugins/user_interface/now_playing/dist/app/Handler.js:115:37) Sep 09 11:45:40 volumio volumio[921]: at /data/plugins/user_interface/now_playing/dist/app/Router.js:47:13 Sep 09 11:45:40 volumio volumio[921]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) Sep 09 11:45:40 volumio volumio[921]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:149:13) Sep 09 11:45:40 volumio volumio[921]: at Route.dispatch (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/route.js:119:3) Sep 09 11:45:40 volumio volumio[921]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) Sep 09 11:45:40 volumio volumio[921]: at /data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:284:15 Sep 09 11:45:40 volumio volumio[921]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:365:14) Sep 09 11:45:40 volumio volumio[921]: at param (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:376:14) Sep 09 11:45:40 volumio volumio[921]: at Function.process_params (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:421:3) Sep 09 11:45:40 volumio volumio[921]: at next (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:280:10) Sep 09 11:45:40 volumio volumio[921]: at Function.handle (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:175:3) Sep 09 11:45:40 volumio volumio[921]: at router (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/index.js:47:12) Sep 09 11:45:40 volumio volumio[921]: at Layer.handle [as handle_request] (/data/plugins/user_interface/now_playing/node_modules/express/lib/router/layer.js:95:5) Sep 09 11:45:40 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:40 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:40 volumio volumio[921]: info: Listing playlists Sep 09 11:45:40 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:40 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:40 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:40 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:40 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:40 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:40 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:40 volumio go-librespot[1568]: time="2024-09-09T11:45:40+08: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]" Sep 09 11:45:40 volumio go-librespot[1568]: time="2024-09-09T11:45:40+08: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]" Sep 09 11:45:40 volumio go-librespot[1568]: time="2024-09-09T11:45:40+08: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]" Sep 09 11:45:40 volumio go-librespot[1568]: time="2024-09-09T11:45:40+08:00" level=debug msg="zeroconf server listening on port 46849" Sep 09 11:45:41 volumio go-librespot[1568]: time="2024-09-09T11:45:41+08:00" level=debug msg="obtained new client token: AAAhNhnH7ny+V4jm12SjbyJ3EYiE69WOFlQVOwuK1u1TbuPNb0rV72FRQlHCVkLzKOmJNnXyqfd2HeJ6+kp4LMyyh9oPeG6n8tzdYQgCNvWDVIBpRxXjFaHaz4r3rlWzzUPEia/d60PIO9AbMGbiQI3DxT5c4Zh5dA6HPB7zpYXVHtlEn/VnJsALFKHcQLOU+FESu0Yaa59zN1W5vICya4Os5EjS/pIJEscDPgog7pLEfs8x2zVcKVGPhg==" Sep 09 11:45:41 volumio go-librespot[1568]: time="2024-09-09T11:45:41+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:41 volumio go-librespot[1568]: time="2024-09-09T11:45:41+08:00" level=debug msg="completed challenge" Sep 09 11:45:41 volumio go-librespot[1568]: time="2024-09-09T11:45:41+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:42 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:42 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:42 volumio volumio[921]: info: Listing playlists Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:42 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:42 volumio volumio[921]: info: Listing playlists Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:42 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:42 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:42 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:42 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:42 volumio volumio[921]: info: Listing playlists Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:42 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:42 volumio volumio[921]: info: Listing playlists Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:42 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:42 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:43 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 23 Sep 09 11:45:43 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:43 volumio volumio[921]: info: Listing playlists Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:43 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:43 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:43 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:43 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:43 volumio volumio[921]: info: Listing playlists Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:43 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:43 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:43 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:43 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:44 volumio volumio[921]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/%C3%8B%C3%AF%C3%A9%C2%AA/263c992d-3489-468f-b4e8-1d738b6b0062.jpg' Sep 09 11:45:44 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Sep 09 11:45:44 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:45 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:45 volumio go-librespot[1614]: Librespot-go daemon starting... Sep 09 11:45:45 volumio go-librespot[1614]: time="2024-09-09T11:45:45+08:00" level=info msg="generated new device id: c28c5d1d75e7c7d59f3dd019d3e3140b2ce2830a" Sep 09 11:45:45 volumio go-librespot[1614]: time="2024-09-09T11:45:45+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:45 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:45 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:45 volumio volumio[921]: info: Listing playlists Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:45 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:45 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:45 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:45 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:45 volumio volumio[921]: info: Listing playlists Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:45 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:45 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:45 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:45 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:45 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:45 volumio go-librespot[1614]: time="2024-09-09T11:45:45+08:00" level=debug msg="new websocket client" Sep 09 11:45:45 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:45:45 volumio go-librespot[1614]: time="2024-09-09T11:45:45+08: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]" Sep 09 11:45:45 volumio go-librespot[1614]: time="2024-09-09T11:45:45+08: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]" Sep 09 11:45:45 volumio go-librespot[1614]: time="2024-09-09T11:45:45+08: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]" Sep 09 11:45:45 volumio go-librespot[1614]: time="2024-09-09T11:45:45+08:00" level=debug msg="zeroconf server listening on port 40897" Sep 09 11:45:46 volumio go-librespot[1614]: time="2024-09-09T11:45:46+08:00" level=debug msg="obtained new client token: AABuM3qo1TVz1v0OBe0AesBRhyRMXTyMZkuH+9gAGdY6znlhMPEGm8/eNEU40hpAGMKKv/+3QnVXg5nIVjtz+NDp3fNpSwsGNC5AJ5LLVd389ZvSYhBgY3ALQaRlu0b8DfTZS9+uYbnhod8I6mlwZ2WkSf/raw43Jet1iSfcMpg2mXC8uNF/0G5VnvD13JlS3FCNVqGMpWkkEeapkj5Fj9bWolSIsUzSbtWttCEsFsq4DseTcl7WLWTTcQ==" Sep 09 11:45:46 volumio go-librespot[1614]: time="2024-09-09T11:45:46+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:46 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:46 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:46 volumio volumio[921]: info: Listing playlists Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:46 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:46 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:46 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:46 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:46 volumio volumio[921]: info: Listing playlists Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:46 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:46 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:46 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:46 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:47 volumio go-librespot[1614]: time="2024-09-09T11:45:47+08:00" level=debug msg="completed challenge" Sep 09 11:45:47 volumio go-librespot[1614]: time="2024-09-09T11:45:47+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:47 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:45:47 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:47 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:47 volumio volumio[921]: info: Listing playlists Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:47 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:47 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:47 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:47 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:47 volumio volumio[921]: info: Listing playlists Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:47 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:47 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:47 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:47 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:48 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 24 Sep 09 11:45:48 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:48 volumio volumio[921]: info: Listing playlists Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:48 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:48 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:48 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:48 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:48 volumio volumio[921]: info: Listing playlists Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:48 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:48 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:48 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:48 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:45:48 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:48 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:45:48 volumio volumio[921]: (node:921) 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: 14) Sep 09 11:45:48 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:48 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:48 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:49 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:49 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:49 volumio volumio[921]: info: Listing playlists Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:49 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:49 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:49 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:49 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:49 volumio volumio[921]: info: Listing playlists Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:49 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:49 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:49 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:49 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:50 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:50 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:50 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Sep 09 11:45:50 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:50 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:50 volumio go-librespot[1622]: Librespot-go daemon starting... Sep 09 11:45:50 volumio go-librespot[1622]: time="2024-09-09T11:45:50+08:00" level=info msg="generated new device id: a652e4d91a1be7fedff80441322247c5eb2deeb0" Sep 09 11:45:50 volumio go-librespot[1622]: time="2024-09-09T11:45:50+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:50 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:50 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:50 volumio volumio[921]: info: Listing playlists Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:50 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:50 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:50 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:50 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:50 volumio volumio[921]: info: Listing playlists Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:50 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:50 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:50 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:50 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:51 volumio go-librespot[1622]: time="2024-09-09T11:45:51+08: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]" Sep 09 11:45:51 volumio go-librespot[1622]: time="2024-09-09T11:45:51+08: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]" Sep 09 11:45:51 volumio go-librespot[1622]: time="2024-09-09T11:45:51+08: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]" Sep 09 11:45:51 volumio go-librespot[1622]: time="2024-09-09T11:45:51+08:00" level=debug msg="zeroconf server listening on port 35211" Sep 09 11:45:51 volumio go-librespot[1622]: time="2024-09-09T11:45:51+08:00" level=debug msg="obtained new client token: AABQfA1OqrW2n7VsfoBMcMTE9kb394qhCR6VdpJYaoYW7zld3US5KXSb2VIG6a5QmM1Vqejem+PB4N5/b3c2XKFj6+6OaGFUEXK6UdMk9q9OHXh8ixyQ0Ma+DeHf4hH99bxD3iQ63wJj+CzRA80KWFAiWRmGP5VudpOlmGaQPU80bNa9jlmZcBiLEEBjAuFeJifadzDk0u9gD3S8NP7yzV6Sw/h/kpwbHoQxEeE+nEF/plyzcOHeTwr3VAA0" Sep 09 11:45:51 volumio go-librespot[1622]: time="2024-09-09T11:45:51+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:51 volumio go-librespot[1622]: time="2024-09-09T11:45:51+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed solving challenge: failed login: BadCredentials" Sep 09 11:45:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:52 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 25 Sep 09 11:45:52 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:52 volumio volumio[921]: info: Listing playlists Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:52 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:52 volumio volumio[921]: info: Listing playlists Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:52 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 26 Sep 09 11:45:52 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:52 volumio volumio[921]: info: Listing playlists Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:52 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:52 volumio volumio[921]: info: Listing playlists Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:52 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:52 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:53 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:53 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:54 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 26 Sep 09 11:45:54 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:54 volumio volumio[921]: info: Listing playlists Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:54 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:54 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:54 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:54 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:54 volumio volumio[921]: info: Listing playlists Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:54 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:54 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:54 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:54 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:54 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Sep 09 11:45:54 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:54 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:54 volumio go-librespot[1630]: Librespot-go daemon starting... Sep 09 11:45:54 volumio go-librespot[1630]: time="2024-09-09T11:45:54+08:00" level=info msg="generated new device id: b112b928ad70ef839da4b1a4ee453dc010518af5" Sep 09 11:45:54 volumio go-librespot[1630]: time="2024-09-09T11:45:54+08:00" level=debug msg="stored credentials not found" Sep 09 11:45:55 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 26 Sep 09 11:45:55 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:55 volumio volumio[921]: info: Listing playlists Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:55 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:55 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:55 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:55 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:55 volumio volumio[921]: info: Listing playlists Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:55 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:55 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:55 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:55 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:55 volumio go-librespot[1630]: time="2024-09-09T11:45:55+08: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]" Sep 09 11:45:55 volumio go-librespot[1630]: time="2024-09-09T11:45:55+08: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]" Sep 09 11:45:55 volumio go-librespot[1630]: time="2024-09-09T11:45:55+08: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]" Sep 09 11:45:55 volumio go-librespot[1630]: time="2024-09-09T11:45:55+08:00" level=debug msg="zeroconf server listening on port 33019" Sep 09 11:45:55 volumio go-librespot[1630]: time="2024-09-09T11:45:55+08:00" level=debug msg="obtained new client token: AABvLsWvVu+hWnsEN2TJ91U8IZ7Mm2+AjBB9xTWL1Yde/U2VeAJdVXeDepA4LDX9AAzLyL5H8DlweY63udtTbleniTk5YFW6h0Jbolss/PbnWetSeYkDZMdKfUG8/taF0EM+e/OZcd1gxJXIISjyXUS0e3UHGJZ+bnYZlwE4T1/L4x69+bPXRaS5wuNup2FBUXihaSQGdaHoZi9JQjmgWJzM1WjVYVUVNGs628qHPU25ITgIZmk7K7WfP2J5" Sep 09 11:45:56 volumio go-librespot[1630]: time="2024-09-09T11:45:56+08:00" level=debug msg="completed keyexchange" Sep 09 11:45:56 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:56 volumio go-librespot[1630]: time="2024-09-09T11:45:56+08:00" level=debug msg="new websocket client" Sep 09 11:45:56 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:45:56 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 26 Sep 09 11:45:56 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:56 volumio volumio[921]: info: Listing playlists Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:56 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:56 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:56 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:56 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:56 volumio volumio[921]: info: Listing playlists Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:56 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:56 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:56 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:56 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:56 volumio go-librespot[1630]: time="2024-09-09T11:45:56+08:00" level=debug msg="completed challenge" Sep 09 11:45:56 volumio go-librespot[1630]: time="2024-09-09T11:45:56+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:45:56 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:45:56 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:45:56 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:45:57 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:45:57 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:57 volumio volumio[921]: info: Listing playlists Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:57 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:57 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:57 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:57 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:57 volumio volumio[921]: info: Listing playlists Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:57 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:57 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:57 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:57 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:59 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:45:59 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:59 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:45:59 volumio volumio[921]: (node:921) 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: 15) Sep 09 11:45:59 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:59 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:59 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:45:59 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:59 volumio volumio[921]: info: Listing playlists Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:59 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:59 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:59 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:59 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:45:59 volumio volumio[921]: info: Listing playlists Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:45:59 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:45:59 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:45:59 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:45:59 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:45:59 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:45:59 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:45:59 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:45:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Sep 09 11:45:59 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:45:59 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:45:59 volumio go-librespot[1639]: Librespot-go daemon starting... Sep 09 11:45:59 volumio go-librespot[1639]: time="2024-09-09T11:45:59+08:00" level=info msg="generated new device id: d945c86e1c7fd303364f7da9755af0ed11727add" Sep 09 11:45:59 volumio go-librespot[1639]: time="2024-09-09T11:45:59+08:00" level=debug msg="stored credentials not found" Sep 09 11:46:00 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:46:00 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:00 volumio volumio[921]: info: Listing playlists Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:00 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:00 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:00 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:00 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:00 volumio volumio[921]: info: Listing playlists Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:00 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:00 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:00 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:00 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:00 volumio go-librespot[1639]: time="2024-09-09T11:46:00+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 09 11:46:00 volumio go-librespot[1639]: time="2024-09-09T11:46:00+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 09 11:46:00 volumio go-librespot[1639]: time="2024-09-09T11:46:00+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 09 11:46:00 volumio go-librespot[1639]: time="2024-09-09T11:46:00+08:00" level=debug msg="zeroconf server listening on port 41771" Sep 09 11:46:00 volumio go-librespot[1639]: time="2024-09-09T11:46:00+08:00" level=debug msg="obtained new client token: AADWk/XWVpJSp57rbtA612teMDhFpPqez0zuLw7BZfrMaI5XdoXuGP/YyplfyBCaw4v9hdGThn66RmQB3NmTqbjP/96whKfq4Vfy7DxLv4qo0S78XIxepeB2HueN3cYyK8ChScuxlN98IJUq8x/AnFv2QYRkSJaiAa/ozeZ9xkAJG6pbvo8byugMywGRBQPjbH3Aee/va5r1IF52Yytw8TMTdXQJTFPw8RygqFL8J92Hxl5S8Bh4BvTsWEc2" Sep 09 11:46:01 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:46:01 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:01 volumio volumio[921]: info: Listing playlists Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:01 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:01 volumio volumio[921]: info: Listing playlists Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:01 volumio go-librespot[1639]: time="2024-09-09T11:46:01+08:00" level=debug msg="completed keyexchange" Sep 09 11:46:01 volumio volumio[921]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/%C3%8E%C2%B4%C3%96%C2%AA%C3%92%C3%95%C3%8A%C3%B5%C2%BC%C3%92/4d38221b-4251-452c-a908-5a59e42106f1.jpg' Sep 09 11:46:01 volumio go-librespot[1639]: time="2024-09-09T11:46:01+08:00" level=debug msg="completed challenge" Sep 09 11:46:01 volumio go-librespot[1639]: time="2024-09-09T11:46:01+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:46:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:46:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:46:01 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 28 Sep 09 11:46:01 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:01 volumio volumio[921]: info: Listing playlists Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:01 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:01 volumio volumio[921]: info: Listing playlists Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:01 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:01 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:02 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:46:02 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:46:03 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 28 Sep 09 11:46:03 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:03 volumio volumio[921]: info: Listing playlists Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:03 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:03 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:03 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:03 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:03 volumio volumio[921]: info: Listing playlists Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:03 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:03 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:03 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:03 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:04 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:46:04 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:04 volumio volumio[921]: info: Listing playlists Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:04 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:04 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:04 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:04 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:04 volumio volumio[921]: info: Listing playlists Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:04 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:04 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:04 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:04 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:46:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Sep 09 11:46:04 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:46:05 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:46:05 volumio go-librespot[1647]: Librespot-go daemon starting... Sep 09 11:46:05 volumio go-librespot[1647]: time="2024-09-09T11:46:05+08:00" level=info msg="generated new device id: 4cc69f5b6a4eccc23ce81f6ee45f56b463928c8a" Sep 09 11:46:05 volumio go-librespot[1647]: time="2024-09-09T11:46:05+08:00" level=debug msg="stored credentials not found" Sep 09 11:46:05 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:46:05 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:05 volumio volumio[921]: info: Listing playlists Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:05 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:05 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:05 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:05 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:05 volumio volumio[921]: info: Listing playlists Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:05 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:05 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:05 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:05 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:05 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:46:05 volumio go-librespot[1647]: time="2024-09-09T11:46:05+08:00" level=debug msg="new websocket client" Sep 09 11:46:05 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:46:05 volumio go-librespot[1647]: time="2024-09-09T11:46:05+08: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]" Sep 09 11:46:05 volumio go-librespot[1647]: time="2024-09-09T11:46:05+08: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]" Sep 09 11:46:05 volumio go-librespot[1647]: time="2024-09-09T11:46:05+08: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]" Sep 09 11:46:05 volumio go-librespot[1647]: time="2024-09-09T11:46:05+08:00" level=debug msg="zeroconf server listening on port 45183" Sep 09 11:46:06 volumio go-librespot[1647]: time="2024-09-09T11:46:06+08:00" level=debug msg="obtained new client token: AABfQZV9djGkgw2208wOXVqBQVgL6uyeYT1rTaLMG/mdhv7W1X6w0/1/KJLxDOXjShTYSyMI778+aBr3vfeL8JzVLffdnJgt9wepzUz02arv4ZUVW4ESIC/PrnxMb+09RTubLuck6NS5TKQ68fQ0F7PBRZQ6o00LFR9iiuO6a0eq61rbzIlVl9R/WINfLuSytkMbNhTp/mRcra11QS1vE7QVSy+1jtKu3D0S6hH5FTvI4Q25Dd//dEqnJw==" Sep 09 11:46:06 volumio go-librespot[1647]: time="2024-09-09T11:46:06+08:00" level=debug msg="completed keyexchange" Sep 09 11:46:06 volumio go-librespot[1647]: time="2024-09-09T11:46:06+08:00" level=debug msg="completed challenge" Sep 09 11:46:07 volumio go-librespot[1647]: time="2024-09-09T11:46:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:46:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:46:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:46:07 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:46:07 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 28 Sep 09 11:46:07 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:07 volumio volumio[921]: info: Listing playlists Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:07 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:07 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:07 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:07 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:07 volumio volumio[921]: info: Listing playlists Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:07 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:07 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:07 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:07 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:08 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:46:08 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:46:08 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:46:08 volumio volumio[921]: (node:921) 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: 16) Sep 09 11:46:08 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 28 Sep 09 11:46:08 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:08 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:09 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 28 Sep 09 11:46:09 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:09 volumio volumio[921]: info: Listing playlists Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:09 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:09 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:09 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:09 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:09 volumio volumio[921]: info: Listing playlists Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:09 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:09 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:09 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:09 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:10 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:46:10 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:46:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:46:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Sep 09 11:46:10 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:46:10 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:46:10 volumio go-librespot[1656]: Librespot-go daemon starting... Sep 09 11:46:10 volumio go-librespot[1656]: time="2024-09-09T11:46:10+08:00" level=info msg="generated new device id: 35541ba559003c3391910f381c8801b4c1f88ba7" Sep 09 11:46:10 volumio go-librespot[1656]: time="2024-09-09T11:46:10+08:00" level=debug msg="stored credentials not found" Sep 09 11:46:11 volumio go-librespot[1656]: time="2024-09-09T11:46:11+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 09 11:46:11 volumio go-librespot[1656]: time="2024-09-09T11:46:11+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Sep 09 11:46:11 volumio go-librespot[1656]: time="2024-09-09T11:46:11+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Sep 09 11:46:11 volumio go-librespot[1656]: time="2024-09-09T11:46:11+08:00" level=debug msg="zeroconf server listening on port 39869" Sep 09 11:46:11 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 28 Sep 09 11:46:11 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:11 volumio volumio[921]: info: Listing playlists Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:11 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:11 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:11 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:11 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:11 volumio volumio[921]: info: Listing playlists Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:11 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:11 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:11 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:11 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:11 volumio go-librespot[1656]: time="2024-09-09T11:46:11+08:00" level=debug msg="obtained new client token: AACQc0qAEi4mNoSEA1l8kTRxy8L/Ss+Vwghugv507TU1O2H6vZ2UDRqSZzBOXZQ1eP6u++rSA0j4Y88wsU0+Q+HjJh++soIaakqlGSzbO7kWpqE6XzNVcNcLwwZRhbUHKhEB7+mp+eR8mZz6GR2/C2Z07jZYJ4tQe7ChGFNtd9wVuDYNFsJ1wcZmwdMevXeGD2bOGQqyTznDhCkOo9Vg2JvCf2jGhgjrGdIKzsaU8rIRVM6XeSTroE8BZVA8" Sep 09 11:46:11 volumio go-librespot[1656]: time="2024-09-09T11:46:11+08:00" level=debug msg="completed keyexchange" Sep 09 11:46:12 volumio go-librespot[1656]: time="2024-09-09T11:46:12+08:00" level=debug msg="completed challenge" Sep 09 11:46:12 volumio go-librespot[1656]: time="2024-09-09T11:46:12+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:46:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:46:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:46:13 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:46:13 volumio volumio[921]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:46:13 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:46:13 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:13 volumio volumio[921]: info: Listing playlists Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:13 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:13 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:13 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:13 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:13 volumio volumio[921]: info: Listing playlists Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:13 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:13 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:13 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:13 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:14 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:46:14 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:14 volumio volumio[921]: info: Listing playlists Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:14 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:14 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:14 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:14 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:14 volumio volumio[921]: info: Listing playlists Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:14 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:14 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:14 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:14 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:46:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Sep 09 11:46:15 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:46:15 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:46:15 volumio go-librespot[1665]: Librespot-go daemon starting... Sep 09 11:46:15 volumio go-librespot[1665]: time="2024-09-09T11:46:15+08:00" level=info msg="generated new device id: e6658406725dd9fd739d45b28c952ad7269d3c4a" Sep 09 11:46:15 volumio go-librespot[1665]: time="2024-09-09T11:46:15+08:00" level=debug msg="stored credentials not found" Sep 09 11:46:16 volumio volumio[921]: info: Initializing connection to go-librespot Websocket Sep 09 11:46:16 volumio volumio[921]: info: Connection to go-librespot Websocket established Sep 09 11:46:16 volumio go-librespot[1665]: time="2024-09-09T11:46:16+08:00" level=debug msg="new websocket client" Sep 09 11:46:16 volumio go-librespot[1665]: time="2024-09-09T11:46:16+08: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]" Sep 09 11:46:16 volumio go-librespot[1665]: time="2024-09-09T11:46:16+08: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]" Sep 09 11:46:16 volumio go-librespot[1665]: time="2024-09-09T11:46:16+08: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]" Sep 09 11:46:16 volumio go-librespot[1665]: time="2024-09-09T11:46:16+08:00" level=debug msg="zeroconf server listening on port 41535" Sep 09 11:46:16 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 27 Sep 09 11:46:16 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:16 volumio volumio[921]: info: Listing playlists Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:16 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:16 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:16 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:16 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:16 volumio volumio[921]: info: Listing playlists Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:16 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:16 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:16 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:16 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:17 volumio go-librespot[1665]: time="2024-09-09T11:46:17+08:00" level=debug msg="obtained new client token: AAAfrXIAsVwx71GdiQZj0UUeyZujfJOHQPr7LmVyh7qTTl4FPWAkpwKjCw/D51zrRT8peYEhYCM0ZOArqLGewi0MPFQyGerm+0M90JgPk8NHx2CHz0w2io0pwbBcFm9M0d3KZ0jCn+Jm17kokkhFpJIuwCkhY+1YnzgUW0e/QfSx8V6a75Shl51WL/6B/b5jZVBQhmjl7z1GlDigNvSJ9DMcBF3wkZTm9R/RVSpjpr+ogcx3Po/YaArcNw==" Sep 09 11:46:17 volumio go-librespot[1665]: time="2024-09-09T11:46:17+08:00" level=debug msg="completed keyexchange" Sep 09 11:46:17 volumio go-librespot[1665]: time="2024-09-09T11:46:17+08:00" level=debug msg="completed challenge" Sep 09 11:46:17 volumio go-librespot[1665]: time="2024-09-09T11:46:17+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Sep 09 11:46:17 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 09 11:46:17 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 09 11:46:17 volumio volumio[921]: info: Connection to go-librespot Websocket closed Sep 09 11:46:18 volumio volumio[921]: verbose: New Socket.io Connection to 192.168.31.88:3000 from 192.168.31.200 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Edg/128.0.0.0 Engine version: 3 Transport: polling Total Clients: 26 Sep 09 11:46:18 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:18 volumio volumio[921]: info: Listing playlists Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:18 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:18 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:18 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:18 volumio volumio[921]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Sep 09 11:46:18 volumio volumio[921]: info: Listing playlists Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetQueue Sep 09 11:46:18 volumio volumio[921]: info: CoreStateMachine::getQueue Sep 09 11:46:18 volumio volumio[921]: info: CorePlayQueue::getQueue Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetVisibleSources Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 09 11:46:18 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:18 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:19 volumio volumio[921]: info: Getting Spotify volume Sep 09 11:46:19 volumio volumio[921]: (node:921) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 09 11:46:19 volumio volumio[921]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Sep 09 11:46:19 volumio volumio[921]: (node:921) 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: 17) Sep 09 11:46:19 volumio volumio[921]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 26 Sep 09 11:46:19 volumio volumio[921]: info: CoreCommandRouter::volumioGetState Sep 09 11:46:19 volumio volumio[921]: info: CorePlayQueue::getTrack 0 Sep 09 11:46:20 volumio volumio[921]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 09 11:46:20 volumio volumio[921]: Error: socket hang up Sep 09 11:46:20 volumio volumio[921]: at connResetException (internal/errors.js:607:14) Sep 09 11:46:20 volumio volumio[921]: at Socket.socketOnEnd (_http_client.js:493:23) Sep 09 11:46:20 volumio volumio[921]: at Socket.emit (events.js:327:22) Sep 09 11:46:20 volumio volumio[921]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 09 11:46:20 volumio volumio[921]: at processTicksAndRejections (internal/process/task_queues.js:80:21) { Sep 09 11:46:20 volumio volumio[921]: code: 'ECONNRESET' Sep 09 11:46:20 volumio volumio[921]: } Sep 09 11:46:20 volumio volumio[921]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 09 11:46:20 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 09 11:46:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Sep 09 11:46:20 volumio systemd[1]: Stopped go-librespot Daemon. Sep 09 11:46:21 volumio systemd[1]: Started go-librespot Daemon. Sep 09 11:46:21 volumio go-librespot[1682]: Librespot-go daemon starting... Sep 09 11:46:21 volumio go-librespot[1682]: time="2024-09-09T11:46:21+08:00" level=info msg="generated new device id: 80a15a409f97f6a31f6ce3070586d006c5b20931" Sep 09 11:46:21 volumio go-librespot[1682]: time="2024-09-09T11:46:21+08:00" level=debug msg="stored credentials not found" Sep 09 11:46:21 volumio sudo[1690]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-09 11:45 Sep 09 11:46:21 volumio sudo[1690]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"