-- Logs begin at Tue 2024-10-08 23:46:56 CST, end at Wed 2024-10-09 00:04:54 CST. -- Oct 09 00:03:01 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:01 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 81. Oct 09 00:03:01 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:01 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:01 my-player go-librespot[5164]: Librespot-go daemon starting... Oct 09 00:03:01 my-player go-librespot[5164]: time="2024-10-09T00:03:01+08:00" level=info msg="generated new device id: c2670505ed0858b0e2cc304530a820a811588f8e" Oct 09 00:03:01 my-player go-librespot[5164]: time="2024-10-09T00:03:01+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:01 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:01 my-player go-librespot[5164]: time="2024-10-09T00:03:01+08:00" level=debug msg="new websocket client" Oct 09 00:03:01 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:03:01 my-player go-librespot[5164]: time="2024-10-09T00:03:01+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]" Oct 09 00:03:01 my-player go-librespot[5164]: time="2024-10-09T00:03:01+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]" Oct 09 00:03:01 my-player go-librespot[5164]: time="2024-10-09T00:03:01+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]" Oct 09 00:03:01 my-player go-librespot[5164]: time="2024-10-09T00:03:01+08:00" level=debug msg="zeroconf server listening on port 46043" Oct 09 00:03:02 my-player go-librespot[5164]: time="2024-10-09T00:03:02+08:00" level=debug msg="obtained new client token: AAB1chHqDLrc47+UgXnRc1UiKUnW0VtPH1oBLSCTyFi0d90ZW8IHXssxrGYIrNSBAsR17J0onwQDLx4AwwCZ4nXFFmE1ghuzB2hw4BuvepoH1/O+GXROANlqw6b4ML5UhppM5aGLiB+5ocPKGtjlnyqEtJlZNwLn2gU8i4ZZsT22QV0sMIAkQl0ALhSNq1caBOUM/PulvsVhKhu7yX0vfmX6SWOSEZNtvk9ZFm8Fd+xKBuZC/SPHsFbuSR/MzmhO" Oct 09 00:03:02 my-player go-librespot[5164]: time="2024-10-09T00:03:02+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:02 my-player go-librespot[5164]: time="2024-10-09T00:03:02+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:03 my-player volumiologrotate[792]: ls: cannot access '/var/log/samba/log.wb-MY': No such file or directory Oct 09 00:03:03 my-player volumiologrotate[792]: ls: cannot access 'PLAYER': No such file or directory Oct 09 00:03:03 my-player go-librespot[5164]: time="2024-10-09T00:03:03+08:00" level=debug msg="completed challenge" Oct 09 00:03:03 my-player go-librespot[5164]: time="2024-10-09T00:03:03+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" Oct 09 00:03:03 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:03 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:03 my-player volumio[1214]: info: Connection to go-librespot Websocket closed Oct 09 00:03:04 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:03:04 my-player volumio[1214]: (node:1214) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:04 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:03:04 my-player volumio[1214]: (node:1214) 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: 42) Oct 09 00:03:04 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:03:04 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:04 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:04 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:03:06 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:06 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:06 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:06 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 82. Oct 09 00:03:06 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:06 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:06 my-player go-librespot[5231]: Librespot-go daemon starting... Oct 09 00:03:06 my-player go-librespot[5231]: time="2024-10-09T00:03:06+08:00" level=info msg="generated new device id: e21bbd7ac76e24bac30270de0a69bb52e19833b5" Oct 09 00:03:06 my-player go-librespot[5231]: time="2024-10-09T00:03:06+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:07 my-player go-librespot[5231]: time="2024-10-09T00:03:07+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]" Oct 09 00:03:07 my-player go-librespot[5231]: time="2024-10-09T00:03:07+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]" Oct 09 00:03:07 my-player go-librespot[5231]: time="2024-10-09T00:03:07+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]" Oct 09 00:03:07 my-player go-librespot[5231]: time="2024-10-09T00:03:07+08:00" level=debug msg="zeroconf server listening on port 37619" Oct 09 00:03:08 my-player go-librespot[5231]: time="2024-10-09T00:03:08+08:00" level=debug msg="obtained new client token: AACsBqLs+njv5h3XcvE/m1yqxxRlBOQ2s2KUXuxkK8DPjONg1CNLoKGWu0hvjXFI0dw/g8igd+FY+wWow3d/PjWniZoBZiSg/H1vw/1b919cGnww7ksKLPbf9UoHFuTZrs0SrsMhbBX+DtjOlPkRv9YxZR4SSUiT2H4O3sZl3uD4ygck+X0LdJM64Vjbm1dWdWGEzGa3t1NGduB09yeS0mbYM1BWKQLqjNxXsDa+iQ4IQlyxCogs1D51mrycZg==" Oct 09 00:03:08 my-player go-librespot[5231]: time="2024-10-09T00:03:08+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:08 my-player go-librespot[5231]: time="2024-10-09T00:03:08+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:08 my-player go-librespot[5231]: time="2024-10-09T00:03:08+08:00" level=debug msg="completed challenge" Oct 09 00:03:09 my-player go-librespot[5231]: time="2024-10-09T00:03:09+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" Oct 09 00:03:09 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:09 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:09 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:09 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:12 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:12 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 83. Oct 09 00:03:12 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:12 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:12 my-player go-librespot[5250]: Librespot-go daemon starting... Oct 09 00:03:12 my-player go-librespot[5250]: time="2024-10-09T00:03:12+08:00" level=info msg="generated new device id: a96f8ee2c277020cf8b0e76de2f787920c8c9eba" Oct 09 00:03:12 my-player go-librespot[5250]: time="2024-10-09T00:03:12+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:12 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:12 my-player go-librespot[5250]: time="2024-10-09T00:03:12+08:00" level=debug msg="new websocket client" Oct 09 00:03:12 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:03:13 my-player go-librespot[5250]: time="2024-10-09T00:03:13+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]" Oct 09 00:03:13 my-player go-librespot[5250]: time="2024-10-09T00:03:13+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]" Oct 09 00:03:13 my-player go-librespot[5250]: time="2024-10-09T00:03:13+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]" Oct 09 00:03:13 my-player go-librespot[5250]: time="2024-10-09T00:03:13+08:00" level=debug msg="zeroconf server listening on port 34361" Oct 09 00:03:13 my-player go-librespot[5250]: time="2024-10-09T00:03:13+08:00" level=debug msg="obtained new client token: AACgKSak4w0cDvoPQyIAkZ8eVbGGbJwAjmi0OKTr7evX7fhelRV0mvlVYIArWIe2VSX7hXlQXw36RQOz8TS+ZJ4Yn9KbZTEPT54760lWoKW8nesmPVXDGUbPzMHdsIG0L0jlmTcO15klxtNLOZ3L+Na8hYEyecOLnIek3yj0zvxqztBaLRD1OLYR1x0Xu0qYUnKkVFeZocctXzcygqLi5g0Ok2I2DIVjDSotw/xy31RurYDGSGb1p6a1NxKLlCFI" Oct 09 00:03:13 my-player go-librespot[5250]: time="2024-10-09T00:03:13+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:13 my-player go-librespot[5250]: time="2024-10-09T00:03:13+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:14 my-player go-librespot[5250]: time="2024-10-09T00:03:14+08:00" level=debug msg="completed challenge" Oct 09 00:03:14 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 09 00:03:14 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 09 00:03:14 my-player volumio[1214]: info: Discovery: Getting this device information Oct 09 00:03:14 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:14 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:14 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 09 00:03:14 my-player go-librespot[5250]: time="2024-10-09T00:03:14+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" Oct 09 00:03:14 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:14 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:14 my-player volumio[1214]: info: Connection to go-librespot Websocket closed Oct 09 00:03:15 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:03:15 my-player volumio[1214]: (node:1214) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:15 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:03:15 my-player volumio[1214]: (node:1214) 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: 43) Oct 09 00:03:15 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:03:15 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:15 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:15 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:03:17 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:17 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:17 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:17 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 84. Oct 09 00:03:17 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:17 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:17 my-player go-librespot[5270]: Librespot-go daemon starting... Oct 09 00:03:17 my-player go-librespot[5270]: time="2024-10-09T00:03:17+08:00" level=info msg="generated new device id: 3adcd39da033574d80da41066fa694d3c1ac0606" Oct 09 00:03:17 my-player go-librespot[5270]: time="2024-10-09T00:03:17+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:18 my-player go-librespot[5270]: time="2024-10-09T00:03:18+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]" Oct 09 00:03:18 my-player go-librespot[5270]: time="2024-10-09T00:03:18+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]" Oct 09 00:03:18 my-player go-librespot[5270]: time="2024-10-09T00:03:18+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]" Oct 09 00:03:18 my-player go-librespot[5270]: time="2024-10-09T00:03:18+08:00" level=debug msg="zeroconf server listening on port 34061" Oct 09 00:03:19 my-player go-librespot[5270]: time="2024-10-09T00:03:19+08:00" level=debug msg="obtained new client token: AABvktmxjmHJJlgq9f2hLGaKdfbVYZHt9QZH+qPc+6jsxWnfI8FRhRklEcz4WQXnQKNqX5v+0/Pe0jamh5D8zPNTFH1Rdk+D3yEEJMN8CBje4Detmlz8+VXNqIIjTzrlcUXrbnifVDvvMpHGGGh3JziAA2Ru0K65ZJdcqexwWDBcW9kWp3XKZvdjs7jVh138kITa5FPe+urK8ESRBt2kXabR15YYD8xIOcbg1qu/EMPTcN6vYgjyStaXTl/NuQ==" Oct 09 00:03:19 my-player go-librespot[5270]: time="2024-10-09T00:03:19+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:19 my-player go-librespot[5270]: time="2024-10-09T00:03:19+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:19 my-player go-librespot[5270]: time="2024-10-09T00:03:19+08:00" level=debug msg="completed challenge" Oct 09 00:03:19 my-player go-librespot[5270]: time="2024-10-09T00:03:19+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" Oct 09 00:03:19 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:19 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:20 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:20 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:23 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:23 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 85. Oct 09 00:03:23 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:23 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:23 my-player go-librespot[5290]: Librespot-go daemon starting... Oct 09 00:03:23 my-player go-librespot[5290]: time="2024-10-09T00:03:23+08:00" level=info msg="generated new device id: 222fdb55a1d69a56522c8a0719736de7f86ed419" Oct 09 00:03:23 my-player go-librespot[5290]: time="2024-10-09T00:03:23+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:23 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:23 my-player go-librespot[5290]: time="2024-10-09T00:03:23+08:00" level=debug msg="new websocket client" Oct 09 00:03:23 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:03:23 my-player go-librespot[5290]: time="2024-10-09T00:03:23+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]" Oct 09 00:03:23 my-player go-librespot[5290]: time="2024-10-09T00:03:23+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]" Oct 09 00:03:23 my-player go-librespot[5290]: time="2024-10-09T00:03:23+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]" Oct 09 00:03:23 my-player go-librespot[5290]: time="2024-10-09T00:03:23+08:00" level=debug msg="zeroconf server listening on port 35287" Oct 09 00:03:24 my-player go-librespot[5290]: time="2024-10-09T00:03:24+08:00" level=debug msg="obtained new client token: AADE3JTL7CRXhMNK2GQrrLXnZim1S3qxbhl7NKBCmw13nCQ8+DENnbaI4bRgTstuqS8n1LjPmyg/bfy/SIu15m8P/erJ89SddnEkyxfkQXef192HKuB6HpOYKdo0qw9gwaqM8mmmpihqB+iAX3mfx1qxzPVtFCetqDNVueNLwIShc2085j5Z9hWhjQXCICUVVVyTYXyotwrwl3wzfFllgtebqaXuJisf8FaWKYDIH8caaWstkod8mCJykEeQ3tMH" Oct 09 00:03:24 my-player go-librespot[5290]: time="2024-10-09T00:03:24+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:24 my-player go-librespot[5290]: time="2024-10-09T00:03:24+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:25 my-player go-librespot[5290]: time="2024-10-09T00:03:25+08:00" level=debug msg="completed challenge" Oct 09 00:03:25 my-player go-librespot[5290]: time="2024-10-09T00:03:25+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" Oct 09 00:03:25 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:25 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:25 my-player volumio[1214]: info: Connection to go-librespot Websocket closed Oct 09 00:03:26 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:03:26 my-player volumio[1214]: (node:1214) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:26 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:03:26 my-player volumio[1214]: (node:1214) 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: 44) Oct 09 00:03:26 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:03:26 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:26 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:26 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:03:28 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:28 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:28 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:28 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 86. Oct 09 00:03:28 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:28 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:28 my-player go-librespot[5310]: Librespot-go daemon starting... Oct 09 00:03:28 my-player go-librespot[5310]: time="2024-10-09T00:03:28+08:00" level=info msg="generated new device id: c5dde7688539962a8f58c23aacc5692f92d9daf4" Oct 09 00:03:28 my-player go-librespot[5310]: time="2024-10-09T00:03:28+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:29 my-player go-librespot[5310]: time="2024-10-09T00:03:29+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]" Oct 09 00:03:29 my-player go-librespot[5310]: time="2024-10-09T00:03:29+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]" Oct 09 00:03:29 my-player go-librespot[5310]: time="2024-10-09T00:03:29+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]" Oct 09 00:03:29 my-player go-librespot[5310]: time="2024-10-09T00:03:29+08:00" level=debug msg="zeroconf server listening on port 46189" Oct 09 00:03:30 my-player go-librespot[5310]: time="2024-10-09T00:03:30+08:00" level=debug msg="obtained new client token: AAAHIrK8zuvJBY0tkaJi8Ftpu7FZl1wnOAOQHpPKp9Pp/uZwbn3SKNZFaTa//elxnkSdFWknPItEuvl/gvY+JuxN3mHbr4ecUjhD5zccp3x0AYJSzKZL+FsSt6hg9c78GqK3Q/bQuV3TsHLPtjs7ANeSKxO0yj403Gx3c2CuFTc2RfBP+vfstQmQt7Y2hhRLNMuiF6TQoRRBYdZX4ADZRJIWwc45VuG95Ps/GdhZR8vH/0tQ6wvPCQ1ItLpIzA==" Oct 09 00:03:30 my-player go-librespot[5310]: time="2024-10-09T00:03:30+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:30 my-player go-librespot[5310]: time="2024-10-09T00:03:30+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:30 my-player go-librespot[5310]: time="2024-10-09T00:03:30+08:00" level=debug msg="completed challenge" Oct 09 00:03:31 my-player go-librespot[5310]: time="2024-10-09T00:03: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" Oct 09 00:03:31 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:31 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:31 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:31 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:34 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:34 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 87. Oct 09 00:03:34 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:34 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:34 my-player go-librespot[5330]: Librespot-go daemon starting... Oct 09 00:03:34 my-player go-librespot[5330]: time="2024-10-09T00:03:34+08:00" level=info msg="generated new device id: 79f074e0d490f7d8dfbb76a4ba623278b71ed62f" Oct 09 00:03:34 my-player go-librespot[5330]: time="2024-10-09T00:03:34+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:34 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:34 my-player go-librespot[5330]: time="2024-10-09T00:03:34+08:00" level=debug msg="new websocket client" Oct 09 00:03:34 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:03:35 my-player go-librespot[5330]: time="2024-10-09T00:03: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 09 00:03:35 my-player go-librespot[5330]: time="2024-10-09T00:03:35+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]" Oct 09 00:03:35 my-player go-librespot[5330]: time="2024-10-09T00:03:35+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]" Oct 09 00:03:35 my-player go-librespot[5330]: time="2024-10-09T00:03:35+08:00" level=debug msg="zeroconf server listening on port 45429" Oct 09 00:03:35 my-player go-librespot[5330]: time="2024-10-09T00:03:35+08:00" level=debug msg="obtained new client token: AADEXyjWv4oq7GjQBH4rKN1HJqmZOkFdjoNlMi61mCX1YeITpwNnF2q+7RixqLhxwrCFJDKmfIb9OBJcEs3faBtNjxctfGz0/1fcgtbWNsX5FF7UrDzJZWo+PHZMp/x0PjW1TGYQNOs2Dvzki8wgu7bj/jOeTLZlGAGBPUSLZe2wUPmDqtIAktk1D06p5bKbGnYal0h00thHaGRinvDwrt+MP1SDebMC3ujnLK2jg5qTGchjZcj9hWAz0b+ZLXvR" Oct 09 00:03:35 my-player go-librespot[5330]: time="2024-10-09T00:03:35+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:35 my-player go-librespot[5330]: time="2024-10-09T00:03:35+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:36 my-player go-librespot[5330]: time="2024-10-09T00:03:36+08:00" level=debug msg="completed challenge" Oct 09 00:03:36 my-player go-librespot[5330]: time="2024-10-09T00:03: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" Oct 09 00:03:36 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:36 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:36 my-player volumio[1214]: info: Connection to go-librespot Websocket closed Oct 09 00:03:37 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:03:37 my-player volumio[1214]: (node:1214) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:37 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:03:37 my-player volumio[1214]: (node:1214) 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: 45) Oct 09 00:03:37 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:03:37 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:37 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:37 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:03:39 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:39 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:39 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:39 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88. Oct 09 00:03:39 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:39 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:39 my-player go-librespot[5349]: Librespot-go daemon starting... Oct 09 00:03:39 my-player go-librespot[5349]: time="2024-10-09T00:03:39+08:00" level=info msg="generated new device id: 21a30ba2ec0a4ec83fcd2ee13949095c67f395b2" Oct 09 00:03:39 my-player go-librespot[5349]: time="2024-10-09T00:03:39+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:41 my-player go-librespot[5349]: time="2024-10-09T00:03:41+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]" Oct 09 00:03:41 my-player go-librespot[5349]: time="2024-10-09T00:03:41+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]" Oct 09 00:03:41 my-player go-librespot[5349]: time="2024-10-09T00:03:41+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]" Oct 09 00:03:41 my-player go-librespot[5349]: time="2024-10-09T00:03:41+08:00" level=debug msg="zeroconf server listening on port 44461" Oct 09 00:03:42 my-player go-librespot[5349]: time="2024-10-09T00:03:42+08:00" level=debug msg="obtained new client token: AACoT6LUpgf7gkLZ/6bFzq3tAKCgBVDcacY/F3WGHTgFRwhFqm7RY68LNglxi7+hjzjwoW1gN9ctYV5d4AVa3PKxEE6GqwVjxqotLLNz2jxCphbgooXNz0MA/gTiPfMThvpqwlVucAQaQzoswjVo1FHW7iMf7YPK9qgajotgD2oxtG5xC87ylIG1PJDx3cuOpThcIQJLEaARuha5TFVRII5nrOmkWdmIRx5batLX9ua76ZR4ukx8LszWnmo=" Oct 09 00:03:42 my-player go-librespot[5349]: time="2024-10-09T00:03:42+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070 (error: dial tcp 104.199.241.202:4070: connect: connection refused), retrying with a different AP" Oct 09 00:03:42 my-player go-librespot[5349]: time="2024-10-09T00:03:42+08:00" level=info msg="connected to ap-gae2.spotify.com:443" Oct 09 00:03:42 my-player go-librespot[5349]: time="2024-10-09T00:03:42+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:42 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:42 my-player go-librespot[5349]: time="2024-10-09T00:03:42+08:00" level=debug msg="new websocket client" Oct 09 00:03:42 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:03:42 my-player go-librespot[5349]: time="2024-10-09T00:03:42+08:00" level=debug msg="completed challenge" Oct 09 00:03:43 my-player go-librespot[5349]: time="2024-10-09T00:03:43+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" Oct 09 00:03:43 my-player volumio[1214]: info: Connection to go-librespot Websocket closed Oct 09 00:03:43 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:43 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:44 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 09 00:03:44 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 09 00:03:44 my-player volumio[1214]: info: Discovery: Getting this device information Oct 09 00:03:44 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:44 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:44 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 09 00:03:45 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:03:45 my-player volumio[1214]: (node:1214) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:45 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:03:45 my-player volumio[1214]: (node:1214) 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: 46) Oct 09 00:03:45 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:03:45 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:45 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:45 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:03:46 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:46 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:46 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:46 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 89. Oct 09 00:03:46 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:46 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:46 my-player go-librespot[5371]: Librespot-go daemon starting... Oct 09 00:03:46 my-player go-librespot[5371]: time="2024-10-09T00:03:46+08:00" level=info msg="generated new device id: 3ab4047eb92e4aea348e0b658e6f98584a8d28e5" Oct 09 00:03:46 my-player go-librespot[5371]: time="2024-10-09T00:03:46+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:46 my-player go-librespot[5371]: time="2024-10-09T00:03:46+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]" Oct 09 00:03:46 my-player go-librespot[5371]: time="2024-10-09T00:03:46+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]" Oct 09 00:03:46 my-player go-librespot[5371]: time="2024-10-09T00:03:46+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]" Oct 09 00:03:46 my-player go-librespot[5371]: time="2024-10-09T00:03:46+08:00" level=debug msg="zeroconf server listening on port 43671" Oct 09 00:03:47 my-player go-librespot[5371]: time="2024-10-09T00:03:47+08:00" level=debug msg="obtained new client token: AABogq0IoG0b6GjaWik3BEjCDhy4uHy/t5iyPgv4HD3e84RKrI6GyRB/8mbpRwdViD8XA/HGqKPVep9df05cvfUHnNXCVKiaBIq0gilv6ilbrhkIABp5go/ew6GrsiPFzR3+QiReohPtaGPrCswOMxSJ/GE11QEVyYAh/71jX+ZtNBxYscrqJha1fLu6wBFCpE3ORmF9GqHRDf3j3MuVMsjHJozplG5nnrY8q2CERa2M/dnkZxYuYXOwf/t0CZKv" Oct 09 00:03:47 my-player go-librespot[5371]: time="2024-10-09T00:03:47+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:47 my-player go-librespot[5371]: time="2024-10-09T00:03:47+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:48 my-player go-librespot[5371]: time="2024-10-09T00:03:48+08:00" level=debug msg="completed challenge" Oct 09 00:03:48 my-player go-librespot[5371]: time="2024-10-09T00:03:48+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" Oct 09 00:03:48 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:48 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:49 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:49 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:51 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:51 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90. Oct 09 00:03:51 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:51 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:51 my-player go-librespot[5392]: Librespot-go daemon starting... Oct 09 00:03:51 my-player go-librespot[5392]: time="2024-10-09T00:03:51+08:00" level=info msg="generated new device id: 801c6cf1305d191c45c30894e9b80ee87623da0d" Oct 09 00:03:51 my-player go-librespot[5392]: time="2024-10-09T00:03:51+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:52 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:52 my-player go-librespot[5392]: time="2024-10-09T00:03:52+08:00" level=debug msg="new websocket client" Oct 09 00:03:52 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:03:52 my-player go-librespot[5392]: time="2024-10-09T00:03:52+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]" Oct 09 00:03:52 my-player go-librespot[5392]: time="2024-10-09T00:03:52+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]" Oct 09 00:03:52 my-player go-librespot[5392]: time="2024-10-09T00:03:52+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]" Oct 09 00:03:52 my-player go-librespot[5392]: time="2024-10-09T00:03:52+08:00" level=debug msg="zeroconf server listening on port 46475" Oct 09 00:03:53 my-player go-librespot[5392]: time="2024-10-09T00:03:53+08:00" level=debug msg="obtained new client token: AABjj1DooFmm18dy45jEdNNS6yvwFO7xvFKg665JpQuydbY/FN/u2Xq+BuJ2BRe2bDTwTvh6UcpO+pppuK5+2pprcdQcQw3P5rk6PEdPf9qW7jWrTd8WuBZ0iBGrfn28aUPqEWPNoEJ3dTT2izSfEejsW1XBCsQT2MLV9KYYYSZ3epiDWxqi7pfHIpi3XIjGo7VnUZnJQ0IvIY7Sw8we7TeUTOOr5i0GKMCDKc+dfIs8Ns5ACEJ4PvrrYUbaMMrS" Oct 09 00:03:53 my-player go-librespot[5392]: time="2024-10-09T00:03:53+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:53 my-player go-librespot[5392]: time="2024-10-09T00:03:53+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:53 my-player go-librespot[5392]: time="2024-10-09T00:03:53+08:00" level=debug msg="completed challenge" Oct 09 00:03:53 my-player go-librespot[5392]: time="2024-10-09T00:03:53+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" Oct 09 00:03:53 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:53 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:53 my-player volumio[1214]: info: Connection to go-librespot Websocket closed Oct 09 00:03:55 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:03:55 my-player volumio[1214]: (node:1214) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:55 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:03:55 my-player volumio[1214]: (node:1214) 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: 47) Oct 09 00:03:55 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:03:55 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:03:55 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:03:55 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:03:56 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:03:56 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:03:57 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:03:57 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91. Oct 09 00:03:57 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:03:57 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:03:57 my-player go-librespot[5411]: Librespot-go daemon starting... Oct 09 00:03:57 my-player go-librespot[5411]: time="2024-10-09T00:03:57+08:00" level=info msg="generated new device id: 06614c3ba25de74a37f61160b95ceabcd4825b4c" Oct 09 00:03:57 my-player go-librespot[5411]: time="2024-10-09T00:03:57+08:00" level=debug msg="stored credentials not found" Oct 09 00:03:57 my-player go-librespot[5411]: time="2024-10-09T00:03:57+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]" Oct 09 00:03:57 my-player go-librespot[5411]: time="2024-10-09T00:03:57+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]" Oct 09 00:03:57 my-player go-librespot[5411]: time="2024-10-09T00:03:57+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]" Oct 09 00:03:57 my-player go-librespot[5411]: time="2024-10-09T00:03:57+08:00" level=debug msg="zeroconf server listening on port 39045" Oct 09 00:03:58 my-player go-librespot[5411]: time="2024-10-09T00:03:58+08:00" level=debug msg="obtained new client token: AAA2RnbTHr0IcB1vZjZhc+ZAO4pktfN8ZfJcRRV7TuUJF79JjW5Im4L5QkcqwNfOwj/PyoTRh3VnuUXOzhgiUSG0Ezc9YRoeFafWYBxqZnlbz7mVSPNDRLB4vkIcb9iB4HGilnFTGhFdJQfIDADzMkWjBH70utJivkwx3QFZJzY0iziT66vBodBUjXrnhYdWxFeNjLzXpMl0YFhwnAKVDyBajHQff8qLsUzO0xdeT8Gb/THi3aWyQITaOVaqw0Oo" Oct 09 00:03:58 my-player go-librespot[5411]: time="2024-10-09T00:03:58+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:03:58 my-player go-librespot[5411]: time="2024-10-09T00:03:58+08:00" level=debug msg="completed keyexchange" Oct 09 00:03:59 my-player go-librespot[5411]: time="2024-10-09T00:03:59+08:00" level=debug msg="completed challenge" Oct 09 00:03:59 my-player go-librespot[5411]: time="2024-10-09T00:03:59+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" Oct 09 00:03:59 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:03:59 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:03:59 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:04:00 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:04:02 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:04:02 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92. Oct 09 00:04:02 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:04:02 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:04:02 my-player go-librespot[5430]: Librespot-go daemon starting... Oct 09 00:04:02 my-player go-librespot[5430]: time="2024-10-09T00:04:02+08:00" level=info msg="generated new device id: 3817eda0a4f4536c792400a150be58d5633d4202" Oct 09 00:04:02 my-player go-librespot[5430]: time="2024-10-09T00:04:02+08:00" level=debug msg="stored credentials not found" Oct 09 00:04:03 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:04:03 my-player go-librespot[5430]: time="2024-10-09T00:04:03+08:00" level=debug msg="new websocket client" Oct 09 00:04:03 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:04:03 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:04:03 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:03 my-player volumio[1214]: info: Prefetching next song Oct 09 00:04:03 my-player volumio[1214]: info: DOING PREFETCH IN MPD Oct 09 00:04:03 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand add "USB/DATA/Music/琴歌-关山月/古怨 Ancient Remorse.flac" Oct 09 00:04:03 my-player volumio[1214]: info: sendMpdCommand add "USB/DATA/Music/琴歌-关山月/古怨 Ancient Remorse.flac" took 2 milliseconds Oct 09 00:04:03 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand consume 1 Oct 09 00:04:03 my-player volumio[1214]: info: Oct 09 00:04:03 my-player volumio[1214]: ---------------------------- MPD announces system playlist update Oct 09 00:04:03 my-player volumio[1214]: info: Ignoring MPD Status Update Oct 09 00:04:03 my-player volumio[1214]: info: Oct 09 00:04:03 my-player volumio[1214]: ---------------------------- MPD announces system playlist update Oct 09 00:04:03 my-player volumio[1214]: info: Ignoring MPD Status Update Oct 09 00:04:03 my-player volumio[1214]: info: Oct 09 00:04:03 my-player volumio[1214]: ---------------------------- MPD announces system playlist update Oct 09 00:04:03 my-player volumio[1214]: info: Ignoring MPD Status Update Oct 09 00:04:03 my-player volumio[1214]: info: sendMpdCommand consume 1 took 6 milliseconds Oct 09 00:04:03 my-player volumio[1214]: info: ------------------------------ 5ms Oct 09 00:04:03 my-player volumio[1214]: info: ------------------------------ 3ms Oct 09 00:04:03 my-player volumio[1214]: info: ------------------------------ 3ms Oct 09 00:04:03 my-player volumiologrotate[792]: ls: cannot access '/var/log/samba/log.wb-MY': No such file or directory Oct 09 00:04:03 my-player volumiologrotate[792]: ls: cannot access 'PLAYER': No such file or directory Oct 09 00:04:03 my-player go-librespot[5430]: time="2024-10-09T00:04:03+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]" Oct 09 00:04:03 my-player go-librespot[5430]: time="2024-10-09T00:04:03+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]" Oct 09 00:04:03 my-player go-librespot[5430]: time="2024-10-09T00:04:03+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]" Oct 09 00:04:03 my-player go-librespot[5430]: time="2024-10-09T00:04:03+08:00" level=debug msg="zeroconf server listening on port 34329" Oct 09 00:04:04 my-player go-librespot[5430]: time="2024-10-09T00:04:04+08:00" level=debug msg="obtained new client token: AACo8Z3VMq/DuNb0VUWgOr/aXV+JPh7MJyRIZrWBoCrlL8KZyiQfrfSN1M17BBpBG2hyjQ5z6lgKJVckNuF6nUxm67O0PtTw1oLghYXwr9RvoVItKt5Kme9ulXMJB4vgUPd+VCWCIYumhv6tE0PfuRx3Oc9OMuykra8Gw+Z24kvThzW/kxey4FeI5d5/lAUbNGCSE/MXOcc3A73egpiTC5+ML0YEXFsOwcKti84XBhSAWFToBhVlkGkfMhuDig==" Oct 09 00:04:04 my-player go-librespot[5430]: time="2024-10-09T00:04:04+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:04:04 my-player go-librespot[5430]: time="2024-10-09T00:04:04+08:00" level=debug msg="completed keyexchange" Oct 09 00:04:04 my-player go-librespot[5430]: time="2024-10-09T00:04:04+08:00" level=debug msg="completed challenge" Oct 09 00:04:05 my-player go-librespot[5430]: time="2024-10-09T00:04: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" Oct 09 00:04:05 my-player systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 09 00:04:05 my-player systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 09 00:04:05 my-player volumio[1214]: info: Connection to go-librespot Websocket closed Oct 09 00:04:06 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:04:06 my-player volumio[1214]: (node:1214) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:04:06 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Oct 09 00:04:06 my-player volumio[1214]: (node:1214) 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: 48) Oct 09 00:04:06 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:04:06 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:04:06 my-player volumio[1214]: info: CorePlayQueue::getTrack 0 Oct 09 00:04:06 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:07 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 09 00:04:07 my-player volumio[1214]: info: CURURI: music-library Oct 09 00:04:07 my-player volumio[1214]: info: Preload queue cleared Oct 09 00:04:07 my-player volumio[1214]: info: CoreStateMachine::startPlaybackTimer Oct 09 00:04:07 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:07 my-player volumio[1214]: info: CoreStateMachine::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::volumioPushState Oct 09 00:04:08 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:08 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:04:08 my-player volumio[1214]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 09 00:04:08 my-player volumio[1214]: info: Oct 09 00:04:08 my-player volumio[1214]: ---------------------------- MPD announces system playlist update Oct 09 00:04:08 my-player volumio[1214]: info: Ignoring MPD Status Update Oct 09 00:04:08 my-player volumio[1214]: info: Oct 09 00:04:08 my-player volumio[1214]: ---------------------------- MPD announces state update: player Oct 09 00:04:08 my-player volumio[1214]: info: ControllerMpd::getState Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand status Oct 09 00:04:08 my-player volumio[1214]: info: Oct 09 00:04:08 my-player volumio[1214]: ---------------------------- MPD announces system playlist update Oct 09 00:04:08 my-player volumio[1214]: info: Ignoring MPD Status Update Oct 09 00:04:08 my-player volumio[1214]: info: Oct 09 00:04:08 my-player volumio[1214]: ---------------------------- MPD announces state update: player Oct 09 00:04:08 my-player volumio[1214]: info: ControllerMpd::getState Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand status Oct 09 00:04:08 my-player volumio[1214]: info: Oct 09 00:04:08 my-player volumio[1214]: ---------------------------- MPD announces system playlist update Oct 09 00:04:08 my-player volumio[1214]: info: Ignoring MPD Status Update Oct 09 00:04:08 my-player volumio[1214]: info: Oct 09 00:04:08 my-player volumio[1214]: ---------------------------- MPD announces state update: player Oct 09 00:04:08 my-player volumio[1214]: info: ControllerMpd::getState Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand status Oct 09 00:04:08 my-player volumio[1214]: info: ------------------------------ 10ms Oct 09 00:04:08 my-player volumio[1214]: info: sendMpdCommand status took 9 milliseconds Oct 09 00:04:08 my-player volumio[1214]: info: ------------------------------ 9ms Oct 09 00:04:08 my-player volumio[1214]: info: sendMpdCommand status took 8 milliseconds Oct 09 00:04:08 my-player volumio[1214]: info: ------------------------------ 7ms Oct 09 00:04:08 my-player volumio[1214]: info: sendMpdCommand status took 4 milliseconds Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::parseState Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::parseState Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::parseState Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 09 00:04:08 my-player volumio[1214]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 09 00:04:08 my-player volumio[1214]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 09 00:04:08 my-player volumio[1214]: info: sendMpdCommand playlistinfo took 3 milliseconds Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::parseTrackInfo Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::parseTrackInfo Oct 09 00:04:08 my-player volumio[1214]: verbose: ControllerMpd::parseTrackInfo Oct 09 00:04:08 my-player volumio[1214]: info: ControllerMpd::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::servicePushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":215,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"386 Kbps","isStreaming":false,"title":"古怨 Ancient Remorse","artist":"范李彬","album":"中国音乐馆-夸父音乐系列-琴歌-关山月","uri":"USB/DATA/Music/琴歌-关山月/古怨 Ancient Remorse.flac","trackType":"flac"} Oct 09 00:04:08 my-player volumio[1214]: verbose: CURRENT POSITION 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::syncState stateService play Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::syncState currentStatus play Oct 09 00:04:08 my-player volumio[1214]: info: Received an update from plugin. extracting info from payload Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::volumioPushState Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::volumioPushState Oct 09 00:04:08 my-player volumio[1214]: info: ControllerMpd::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::servicePushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":215,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"386 Kbps","isStreaming":false,"title":"古怨 Ancient Remorse","artist":"范李彬","album":"中国音乐馆-夸父音乐系列-琴歌-关山月","uri":"USB/DATA/Music/琴歌-关山月/古怨 Ancient Remorse.flac","trackType":"flac"} Oct 09 00:04:08 my-player volumio[1214]: verbose: CURRENT POSITION 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::syncState stateService play Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::syncState currentStatus play Oct 09 00:04:08 my-player volumio[1214]: info: Received an update from plugin. extracting info from payload Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::volumioPushState Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::volumioPushState Oct 09 00:04:08 my-player volumio[1214]: info: ControllerMpd::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::servicePushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: verbose: STATE SERVICE {"status":"play","position":0,"seek":45,"duration":215,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"386 Kbps","isStreaming":false,"title":"古怨 Ancient Remorse","artist":"范李彬","album":"中国音乐馆-夸父音乐系列-琴歌-关山月","uri":"USB/DATA/Music/琴歌-关山月/古怨 Ancient Remorse.flac","trackType":"flac"} Oct 09 00:04:08 my-player volumio[1214]: verbose: CURRENT POSITION 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::syncState stateService play Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::syncState currentStatus play Oct 09 00:04:08 my-player volumio[1214]: info: Received an update from plugin. extracting info from payload Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::volumioPushState Oct 09 00:04:08 my-player volumio[1214]: info: CoreStateMachine::pushState Oct 09 00:04:08 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::volumioPushState Oct 09 00:04:08 my-player systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 09 00:04:08 my-player systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. Oct 09 00:04:08 my-player systemd[1]: Stopped go-librespot Daemon. Oct 09 00:04:08 my-player systemd[1]: Started go-librespot Daemon. Oct 09 00:04:08 my-player go-librespot[5500]: Librespot-go daemon starting... Oct 09 00:04:08 my-player volumio[1214]: info: ------------------------------ 92ms Oct 09 00:04:08 my-player volumio[1214]: info: ------------------------------ 90ms Oct 09 00:04:08 my-player volumio[1214]: info: ------------------------------ 89ms Oct 09 00:04:08 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:08 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:08 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:08 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:08 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:08 my-player go-librespot[5500]: time="2024-10-09T00:04:08+08:00" level=info msg="generated new device id: 433b157d9066688ee34ed3d1dcedf374a9ed0f1f" Oct 09 00:04:08 my-player go-librespot[5500]: time="2024-10-09T00:04:08+08:00" level=debug msg="stored credentials not found" Oct 09 00:04:08 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 09 00:04:08 my-player volumio[1214]: info: CURURI: music-library/USB Oct 09 00:04:08 my-player volumio[1214]: info: Preload queue cleared Oct 09 00:04:09 my-player go-librespot[5500]: time="2024-10-09T00:04: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Oct 09 00:04:09 my-player go-librespot[5500]: time="2024-10-09T00:04:09+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]" Oct 09 00:04:09 my-player go-librespot[5500]: time="2024-10-09T00:04:09+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]" Oct 09 00:04:09 my-player go-librespot[5500]: time="2024-10-09T00:04:09+08:00" level=debug msg="zeroconf server listening on port 45791" Oct 09 00:04:09 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 09 00:04:09 my-player volumio[1214]: info: CURURI: music-library/USB/DATA Oct 09 00:04:09 my-player volumio[1214]: info: Preload queue cleared Oct 09 00:04:09 my-player go-librespot[5500]: time="2024-10-09T00:04:09+08:00" level=debug msg="obtained new client token: AACwN7Y+3pnXSFACjLl645b7tfuMKNEdkzzIosx4KPTHm+pr8L4PZ1rlh2LnV8PR4So8uB757YiVT8U9aZnr/rdtUBURNWfyZCNxv5whwUKT+M03TodSK0/AVHvH3Ucmerj56LecvxWxnagMcHlAlfaTQr9eFfuf9rNsvbSlMhvzTR/5BXKrsEu558QXc4xepooy5G7Tu9NNwxwAarUkXmCKfHmThw7FekMEVwEAyz57fZiL6ycAOXF0imVQgD6T" Oct 09 00:04:10 my-player go-librespot[5500]: time="2024-10-09T00:04:10+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 09 00:04:10 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 09 00:04:10 my-player volumio[1214]: info: CURURI: music-library/USB/DATA/Music Oct 09 00:04:10 my-player volumio[1214]: info: Preload queue cleared Oct 09 00:04:11 my-player volumio[1214]: info: Initializing connection to go-librespot Websocket Oct 09 00:04:11 my-player go-librespot[5500]: time="2024-10-09T00:04:11+08:00" level=debug msg="new websocket client" Oct 09 00:04:11 my-player volumio[1214]: info: Connection to go-librespot Websocket established Oct 09 00:04:14 my-player volumio[1214]: info: Getting Spotify volume Oct 09 00:04:14 my-player volumio[1214]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Oct 09 00:04:14 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:04:14 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:14 my-player volumio[1214]: SPOTIFY: RECEIVED VOLUMIO VOLUME 34 Oct 09 00:04:14 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Oct 09 00:04:14 my-player volumio[1214]: info: CURURI: music-library/USB/DATA/Music/2004-赵鹏《人声低音炮2·月光森林》 Oct 09 00:04:14 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 09 00:04:14 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 09 00:04:14 my-player volumio[1214]: info: Discovery: Getting this device information Oct 09 00:04:14 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:04:14 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:14 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 09 00:04:14 my-player volumio[1214]: info: Preload queue cleared Oct 09 00:04:26 my-player volumio[1214]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 09 00:04:26 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Oct 09 00:04:26 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 09 00:04:26 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Oct 09 00:04:27 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::volumioGetBrowseSources Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:04:38 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 09 00:04:42 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:04:44 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 09 00:04:44 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 09 00:04:44 my-player volumio[1214]: info: Discovery: Getting this device information Oct 09 00:04:44 my-player volumio[1214]: info: CoreCommandRouter::volumioGetState Oct 09 00:04:44 my-player volumio[1214]: info: CorePlayQueue::getTrack 1 Oct 09 00:04:44 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 09 00:04:46 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:04:50 my-player volumio[1214]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 09 00:04:53 my-player volumio[1214]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 09 00:04:53 my-player volumio[1214]: Error: connect ETIMEDOUT 199.59.149.136:443 Oct 09 00:04:53 my-player volumio[1214]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Oct 09 00:04:53 my-player volumio[1214]: errno: -110, Oct 09 00:04:53 my-player volumio[1214]: code: 'ETIMEDOUT', Oct 09 00:04:53 my-player volumio[1214]: syscall: 'connect', Oct 09 00:04:53 my-player volumio[1214]: address: '199.59.149.136', Oct 09 00:04:53 my-player volumio[1214]: port: 443 Oct 09 00:04:53 my-player volumio[1214]: } Oct 09 00:04:53 my-player volumio[1214]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 09 00:04:54 my-player sudo[5614]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-09 00:03 Oct 09 00:04:54 my-player sudo[5614]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"