-- Logs begin at Sun 2025-02-23 23:15:57 KST, end at Mon 2025-02-24 01:33:59 KST. -- Feb 24 01:32:27 volumio-ap-3 go-librespot[31933]: time="2025-02-24T01:32:27+09:00" level=error msg="did not receive last pong ack from accesspoint, 120s passed" Feb 24 01:32:27 volumio-ap-3 go-librespot[31933]: time="2025-02-24T01:32:27+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.144:35788->104.199.241.202:4070: use of closed network connection" Feb 24 01:32:27 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:27 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:27 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: socket hang up Feb 24 01:32:27 volumio-ap-3 volumio[970]: at connResetException (internal/errors.js:607:14) Feb 24 01:32:27 volumio-ap-3 volumio[970]: at Socket.socketOnEnd (_http_client.js:493:23) Feb 24 01:32:27 volumio-ap-3 volumio[970]: at Socket.emit (events.js:327:22) Feb 24 01:32:27 volumio-ap-3 volumio[970]: at endReadableNT (internal/streams/readable.js:1327:12) Feb 24 01:32:27 volumio-ap-3 volumio[970]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Feb 24 01:32:27 volumio-ap-3 volumio[970]: (node:970) 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: 7732) Feb 24 01:32:27 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:32:30 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:30 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:30 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:32:30 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23038. Feb 24 01:32:30 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:32:30 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: Librespot-go daemon starting... Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09:00" level=info msg="generated new device id: f87806b3b46ec3e9ad7f7876b91e7ecda46e2b2b" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09: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]" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09: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]" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09: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]" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09:00" level=debug msg="zeroconf server listening on port 37173" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09:00" level=debug msg="obtained new client token: AAAjm02JF+ds+YiJf0fkrPQRX6HBK5yqUft77w+6jQVqOtc8Yi6bRkMCcbFWrTQSFjYritmRzwPpoXuMS/Q1I6ouLFSjCXXOKWouzjTWjtgzH5CgfX06yJcStl69jS5ciuISY5IUe54PUPt4dsDGP1VxL84qs+Bc7hVIaQOk0iY+GYrY+WrnAjaC624IoeaSSUsX51Z3ks4uCwzIBmdWIEYHTwx/O/q3igvMKeDe8b27E0OXDQcIe1dwEGowQ9ir" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:32:30 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:30+09:00" level=debug msg="completed keyexchange" Feb 24 01:32:31 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:31+09:00" level=debug msg="completed challenge" Feb 24 01:32:31 volumio-ap-3 go-librespot[32544]: time="2025-02-24T01:32:31+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:32:31 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:31 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:33 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:33 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:34 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:32:34 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23039. Feb 24 01:32:34 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:32:34 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: Librespot-go daemon starting... Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09:00" level=info msg="generated new device id: 16042606d9c1e425e06a0a92516bb3b5d03e13e7" Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09: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]" Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09: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]" Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09: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]" Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09:00" level=debug msg="zeroconf server listening on port 46009" Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09:00" level=debug msg="obtained new client token: AAANN6LowqlIHI1JigjMHWf25BEYmEIEn2e9vC8akuaQ0uZ9SCmxjJ9lkdBAIXxVjOrkAiZeWS//El/gO/Op5qrf6dUNGCTkpv1Emh4rah203SjT8rhOeJfje80JfkF52O//SYKv8vUWeQN3GmeHPCGASfgVBCk894pjVH8tmysWicW+3tJ4lNRPZsLNo5A2G+jHDoJhDK4sfBOOfbn4cgfp4FLXnEnShl6WLGTG7cxQzjEB8NfJQc3SrC22R+xR" Feb 24 01:32:34 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:34+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:32:35 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:35+09:00" level=debug msg="completed keyexchange" Feb 24 01:32:35 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:35+09:00" level=debug msg="completed challenge" Feb 24 01:32:35 volumio-ap-3 go-librespot[32556]: time="2025-02-24T01:32:35+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:32:35 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:35 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:36 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:36 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:38 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:32:38 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23040. Feb 24 01:32:38 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:32:38 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:32:38 volumio-ap-3 go-librespot[32567]: Librespot-go daemon starting... Feb 24 01:32:38 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:38+09:00" level=info msg="generated new device id: 7741f9a137991bd0f3ac89f03ed7d26e5ae9d3e5" Feb 24 01:32:38 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:38+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09: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]" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09: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]" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09: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]" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09:00" level=debug msg="zeroconf server listening on port 39401" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09:00" level=debug msg="obtained new client token: AABFioHxzL3bAPkq2ldMwHQ8W3Q0+kWTOXvRiksIzJe69vokGQ2SiXMWu1tMoDIRUwgNLMmQzxFyV6wY9M/japE67gHhkP7f076Zmlbp1kHi/deHwxqKOIPMksDHXLURB7KlqBfcAEQUrh/9Hh0yJYlhVrf8/tzmu4dLfCE1pzbL27unvJm+hWCiTiQHA2mMak8/5PieeF6HeSPCgAH6OVM5249m1C+jXownt+oMwnEKmh8iGHT6gmC9rU4ddg==" Feb 24 01:32:39 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09:00" level=debug msg="new websocket client" Feb 24 01:32:39 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket established Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09:00" level=debug msg="completed keyexchange" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09:00" level=debug msg="completed challenge" Feb 24 01:32:39 volumio-ap-3 go-librespot[32567]: time="2025-02-24T01:32:39+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:32:39 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:39 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:39 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:32:42 volumio-ap-3 volumio[970]: info: Getting Spotify volume Feb 24 01:32:42 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:42 volumio-ap-3 volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Feb 24 01:32:42 volumio-ap-3 volumio[970]: (node:970) 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: 7733) Feb 24 01:32:42 volumio-ap-3 volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 24 01:32:42 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:32:42 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:32:42 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:42 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:43 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:32:43 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23041. Feb 24 01:32:43 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:32:43 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: Librespot-go daemon starting... Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09:00" level=info msg="generated new device id: 958a492f159ce40dd79c3d734fa4f9b92b717ecb" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09: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]" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09: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]" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09: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]" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09:00" level=debug msg="zeroconf server listening on port 42419" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09:00" level=debug msg="obtained new client token: AACbrKHqGsBztVzLJvyBFbyz5Pt1UA3S6FofIUhqVgFgHYhKju5t5IjdaNfXjhnmJyooLvnNaiMfCQ+LzWC27bHPXqVEEh90ZnbKIuxEXgu/NuxNPCH1j3hqstffbT21dv3a/KEM6+qAPgXmvh5lXkVkK8EUWDiWq4juDmMxXNZtnpxwYMsYlh0rkBS4+nJYhgMAwHsqUzAKad64HH7o5RFx4YlFtWWlshlr/GrnYSRb7xdg9XSRfHrvteU7ij20" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:32:43 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:43+09:00" level=debug msg="completed keyexchange" Feb 24 01:32:44 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:44+09:00" level=debug msg="completed challenge" Feb 24 01:32:44 volumio-ap-3 go-librespot[32589]: time="2025-02-24T01:32:44+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:32:44 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:44 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:45 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:45 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:47 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:32:47 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23042. Feb 24 01:32:47 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:32:47 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: Librespot-go daemon starting... Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09:00" level=info msg="generated new device id: 77e43ac345a55a50bc650fad2cdce8f27dade94d" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09: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]" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09: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]" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09: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]" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09:00" level=debug msg="zeroconf server listening on port 43743" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09:00" level=debug msg="obtained new client token: AAASx9jcAvpRUxzxewhNIMb82eS0mKRlUrkfxb19/ZB1/uj7eNiI9e+6iP8r6ZOm8aOfzv2XEY832SFMYAyBCw+r9Q5zoyJDMpQPaZvYfpxX2qn5dO5HPLjlG3nldMCicr6w4gYuMWrJm9WYpPHJ3dV3IRODuLD4BP9u8JG59kXxcJJ71uNsyVJygac1rFzi/jZN/ARUox0oTQ3CcEt9NxHIBNEYxb5b3rh5Ja3L1Xj3+2JbYZsfWIx3YLv33ZnZ" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:32:47 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:47+09:00" level=debug msg="completed keyexchange" Feb 24 01:32:48 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:48+09:00" level=debug msg="completed challenge" Feb 24 01:32:48 volumio-ap-3 go-librespot[32597]: time="2025-02-24T01:32:48+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:32:48 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:48 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:48 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:48 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:51 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:32:51 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23043. Feb 24 01:32:51 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:32:51 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: Librespot-go daemon starting... Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09:00" level=info msg="generated new device id: 9b5f09f4f13033cd472bff1118e4738f8d2b30ce" Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09: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]" Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09: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]" Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09: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]" Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09:00" level=debug msg="zeroconf server listening on port 44783" Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09:00" level=debug msg="obtained new client token: AAD947iUMXQUrxuSWENkKAw7x9a4nmfDu7uUZxBp5oQoDZWIVpfL8jcNukCMm68Q6bZJbiQbINlgok463Rj16fPPr9R5LKcDMpEK/MD+fD5u/0AgrQgL9pF6DpD3gMpuQR1aj2vBMlwwe2vAfBxYREi7O1OsVNr7g1rU//zqhbS51bq8z6XbONNmfO3dotG7b6r6Pl2rxjaoD0NB4TXUvuZYjO9d1mRFbYjYpkGS+56D9go21sjxHfVDqZzmx8us" Feb 24 01:32:51 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09:00" level=debug msg="new websocket client" Feb 24 01:32:51 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket established Feb 24 01:32:51 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:51+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:32:52 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:52+09:00" level=debug msg="completed keyexchange" Feb 24 01:32:52 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:52+09:00" level=debug msg="completed challenge" Feb 24 01:32:52 volumio-ap-3 go-librespot[32622]: time="2025-02-24T01:32:52+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:32:52 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:52 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:32:52 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:54 volumio-ap-3 nmbd[772]: [2025/02/24 01:32:54.367285, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response) Feb 24 01:32:54 volumio-ap-3 nmbd[772]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.1.144 for name WORKGROUP<1d>. Feb 24 01:32:54 volumio-ap-3 nmbd[772]: This response was from IP 192.168.1.126, reporting an IP address of 192.168.1.126. Feb 24 01:32:54 volumio-ap-3 volumio[970]: info: Getting Spotify volume Feb 24 01:32:54 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:54 volumio-ap-3 volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Feb 24 01:32:54 volumio-ap-3 volumio[970]: (node:970) 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: 7734) Feb 24 01:32:54 volumio-ap-3 volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 24 01:32:54 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:32:54 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:32:55 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:55 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:32:55 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:32:55 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23044. Feb 24 01:32:55 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:32:55 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:32:55 volumio-ap-3 go-librespot[32632]: Librespot-go daemon starting... Feb 24 01:32:55 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:55+09:00" level=info msg="generated new device id: 906123cc5c9343341af8bb702c57118940781881" Feb 24 01:32:55 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:55+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09: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]" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09: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]" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09: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]" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09:00" level=debug msg="zeroconf server listening on port 45815" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09:00" level=debug msg="obtained new client token: AABp+8ilq+di+QnTmQybM/iw0Mj9cin6PgfPogZkLkOnoqZZKgophkX276N0+upgoNIoDIM5XHLyiRFfzLwQTfiPj7SXlI7fIHW+m+xZ361rxJ6yt1PSvMqFi/AvzXRrmXUtWD5KATZdiTl3mCH6IFMm77Kf2Tdn71j19IGTP4DxPuFET+yAudrpLyjsBlNp4OXYYxNYaab99Q3SJO/hXl0zT5ZHFZ4qGhxKz6Q9tLvPZMJ/fRgmuiLdYm+4Fg==" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09:00" level=debug msg="completed keyexchange" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09:00" level=debug msg="completed challenge" Feb 24 01:32:56 volumio-ap-3 go-librespot[32632]: time="2025-02-24T01:32:56+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:32:56 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:32:56 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:32:58 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:32:58 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:00 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:00 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23045. Feb 24 01:33:00 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:00 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: Librespot-go daemon starting... Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09:00" level=info msg="generated new device id: 9655862265a3abd672f10ee7d11b84b4094b08b5" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09: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]" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09: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]" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09: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]" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09:00" level=debug msg="zeroconf server listening on port 43931" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09:00" level=debug msg="obtained new client token: AAAZQnaHWSIpqeU1OKVmPzIEGeYgGwLKp6Dkq7zzXFvxl+5e9iu7x5nE998eyHKN/bb9Ntl6SEPIPrk8zgrZhE4VBdXVJGJE/BzLFzrlab80IVxYGSB8p00bkoOpgqPFTnwdmofWjKYbBWWhvwTpp3wrEk1n/mN5f7QqYUpHNM0aurz64fOJDkfXne1Ea1Y/XKFKswwVZDkRdLXO9Ik49+sUCLcigRGH7zdXZBIOnY5cqJxblN9wm7cltqAHa6jL" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:00 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:00+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:01 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:01+09:00" level=debug msg="completed challenge" Feb 24 01:33:01 volumio-ap-3 go-librespot[32657]: time="2025-02-24T01:33:01+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:01 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:01 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:01 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:01 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:04 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:04 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23046. Feb 24 01:33:04 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:04 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: Librespot-go daemon starting... Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09:00" level=info msg="generated new device id: 16ded1678bae0349d3844f5e3ef93ffdf5cadc2a" Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09: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]" Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09: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]" Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09: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]" Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09:00" level=debug msg="zeroconf server listening on port 45521" Feb 24 01:33:04 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09:00" level=debug msg="new websocket client" Feb 24 01:33:04 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket established Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09:00" level=debug msg="obtained new client token: AAAufe58Vq2tvYC5HtvzjpJ/lcHjec2hR3XHXe+tbPilLDaHDorgjybPhJnhk9Z74rMAx9r5JNg1bnGU549HaA9X91p3kei8d/D+vrMoXvXZM0r5n3IEL/SHQbvAez94iIantw+6SclfIfqcSwcNrM7Cc1lmxCeqd8PSBqAFzjF4eJIrbOsZiPHjJMjw7JkEDIiANMJLEBFJ8OzMoSonEtZ6B02caSL5D/FWJr1QFQFAyqgJLWG0IXaZqr35IG20" Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:04 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:04+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:05 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:05+09:00" level=debug msg="completed challenge" Feb 24 01:33:05 volumio-ap-3 go-librespot[32665]: time="2025-02-24T01:33:05+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:05 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:05 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:05 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:33:07 volumio-ap-3 volumio[970]: info: Getting Spotify volume Feb 24 01:33:07 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:07 volumio-ap-3 volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Feb 24 01:33:07 volumio-ap-3 volumio[970]: (node:970) 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: 7735) Feb 24 01:33:07 volumio-ap-3 volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 24 01:33:07 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:33:07 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:08 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:08 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:08 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:08 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23047. Feb 24 01:33:08 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:08 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: Librespot-go daemon starting... Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09:00" level=info msg="generated new device id: 150e369faa7136ace8a1fae11c21a56fcc032aad" Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09: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]" Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09: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]" Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09: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]" Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09:00" level=debug msg="zeroconf server listening on port 33875" Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09:00" level=debug msg="obtained new client token: AAAw/+al5zTRf1Zty9N4aAPWW4OvrR093mPdc+YWbj6Ipz71BVhndowz3XIVgEUPghJMh0POwlKR8lRDCCZVnJACPonZaJgLTmTKjbk29GrpQ49D/b6dYCUaHpkdA9fkGGU76+ZJnavj4s4TieeAjN1Ekr1FJVPm0mcr8Br3xRIQ+FzTAgPCBAMbCX9VraFgCNd44EvUZM4GIzD92xHQtcm79qnHKJ8dMA90MNeHHHUu5KNxWpyWLdCd5bKyfSIN" Feb 24 01:33:08 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:08+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:09 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:09+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:09 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:09+09:00" level=debug msg="completed challenge" Feb 24 01:33:09 volumio-ap-3 go-librespot[32715]: time="2025-02-24T01:33:09+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:09 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:09 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:11 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:11 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:12 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:12 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23048. Feb 24 01:33:12 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:12 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:12 volumio-ap-3 go-librespot[32739]: Librespot-go daemon starting... Feb 24 01:33:12 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:12+09:00" level=info msg="generated new device id: 9b69ccb4b0ca5812e9e005ca8295e29bc9e67d84" Feb 24 01:33:12 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:12+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09: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]" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09: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]" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09: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]" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09:00" level=debug msg="zeroconf server listening on port 45131" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09:00" level=debug msg="obtained new client token: AAAHHdoN4q5MJYPEC/+sQkuSNFduWm5YLTSTgKvI0KB6mXcAWnWLbWqOq7JqaI1o4s/6HGWDuLRquUDaHeOel1Mjy/illUEzvQzY5GajGetCCNr2rKj45ukggeFVQF5uF1X4xGMow8KOAlpyN7fQshWPi+iKSaeT/ipzQNHshJuUQpQn65hrKuUkbq8VhuN7MqMWEONCMjUEDLU+Rt9Q3PpKv84hJwcPgvdiWBMWuzRGBu01tzRQeSoZoKswWA==" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09:00" level=debug msg="completed challenge" Feb 24 01:33:13 volumio-ap-3 go-librespot[32739]: time="2025-02-24T01:33:13+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:13 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:13 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:14 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:14 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:17 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:17 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23049. Feb 24 01:33:17 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:17 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: Librespot-go daemon starting... Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09:00" level=info msg="generated new device id: 6b823f5b77cc9a1c810ab5cc28e00b754576b3c1" Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09: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]" Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09: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]" Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09: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]" Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09:00" level=debug msg="zeroconf server listening on port 33315" Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09:00" level=debug msg="obtained new client token: AACCHQKYCkPIato7ax4xxCIVaiLci5hDC3zpFBG/uO+Ocdf03ye9S1NFTjc/DSQNJMpA4m5XJkfysdkdZLH+tke18HqhNCbbfevp+RE1aRo+PbeZvLZO5z3M/9Yw62F0JbHvrbtmMVbOBXcX+AF4MwuzNNWbWWEm6DcFwSiRMKuOxfuDZq4SfxUAJ+d10zOwa6KkfIq5LmwF2wsvc7f2j9nFdbzkB9Kgm7MxPquZP1z7oZJyWkmOCw+IQn88usn+" Feb 24 01:33:17 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09:00" level=debug msg="new websocket client" Feb 24 01:33:17 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket established Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:17 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:17+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:18 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:18+09:00" level=debug msg="completed challenge" Feb 24 01:33:18 volumio-ap-3 go-librespot[32748]: time="2025-02-24T01:33:18+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:18 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:18 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:18 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:33:20 volumio-ap-3 volumio[970]: info: Getting Spotify volume Feb 24 01:33:20 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:20 volumio-ap-3 volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Feb 24 01:33:20 volumio-ap-3 volumio[970]: (node:970) 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: 7736) Feb 24 01:33:20 volumio-ap-3 volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 24 01:33:20 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:33:20 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:21 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:21 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:21 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:21 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23050. Feb 24 01:33:21 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:21 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: Librespot-go daemon starting... Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09:00" level=info msg="generated new device id: 8dabf30ddd4898a29acc79b4c9a82994be8bf37c" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09: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]" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09: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]" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09: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]" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09:00" level=debug msg="zeroconf server listening on port 42889" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09:00" level=debug msg="obtained new client token: AABL0AgARHpMLQJBALdfDecEw6VP///ex/0/LBA0iN0YYGB0wPk86m2gQeWJi35cKV/lo7GzL55Svg1gzkZE2RWccXB0RJV5/7K4Y2i6oepvfeo+uLC2BH40D8iQtXT/0bZSZO+0RdFuKeAnwBatR9nAhhkOcjbh8lRLOqaUxA43noXWo/L206cpqg5+bDFa+sKyhKIDg4FspCaRZR6ySZmYtJX5cQAlOZmCPqEhY0CVqKpmRQxZyJyWf+jiXaAw" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:21 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:21+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:22 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:22+09:00" level=debug msg="completed challenge" Feb 24 01:33:22 volumio-ap-3 go-librespot[307]: time="2025-02-24T01:33:22+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:22 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:22 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:24 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:24 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:25 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:25 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23051. Feb 24 01:33:25 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:25 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: Librespot-go daemon starting... Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09:00" level=info msg="generated new device id: efa87cae301bdeee363c835efb3f3672da5ba084" Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09: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]" Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09: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]" Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09: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]" Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09:00" level=debug msg="zeroconf server listening on port 45457" Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09:00" level=debug msg="obtained new client token: AACNOzTt7+BPA8HCkY0AoNgLgAv7jd2KJH6a6yZpRXCLzRYD+9yCt7cso6R2caMYNA/Bc18DWcR7EP7UzWlDi8p/Mz9jihWnXD7HUY1lyw0mqCQxtfK9179Ejnj0JqyRiegj4r/IynY5OHQik3hEvY7QUDzGg6jW0hdCbEPamLrmp2mNrMDfmU5DG3HcDb52HdGAor4qh6ekxkJi7G9z8mQ074QiSrgHJazLhbOJpAh6wrjFCLndzKZVMsemNglU" Feb 24 01:33:25 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:25+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:26 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:26+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:26 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:26+09:00" level=debug msg="completed challenge" Feb 24 01:33:26 volumio-ap-3 go-librespot[319]: time="2025-02-24T01:33:26+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:26 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:26 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:27 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:27 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:29 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:29 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23052. Feb 24 01:33:29 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:29 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:29 volumio-ap-3 go-librespot[345]: Librespot-go daemon starting... Feb 24 01:33:29 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:29+09:00" level=info msg="generated new device id: 0be27a6c04d04c9e0a9a670174ba8c8c7ccbbede" Feb 24 01:33:29 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:29+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09: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]" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09: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]" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09: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]" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09:00" level=debug msg="zeroconf server listening on port 36339" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09:00" level=debug msg="obtained new client token: AAASjFDI0IJ9okcmOXVH42Jc963Rznr2u3gu9VxfGij72+2hbSJ6i/GIrSRHp46XGAY7YhonN5MWFxOFrPnkv8kxFpFsuXmeiAt0geI0vHaKyA4Ck6afWGUto5zn2/x6wNUAyNAEdxgTcFvdP023/ZHKY3O2Q6F3BNZe1xaPvXDe05c4H5I74bo62QBoqCcSki4pwP5Xv72p/kesW7W+HiNs1go85ZPZzu69bdSJziDdim9phXXn8cP9NPkdWA==" Feb 24 01:33:30 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09:00" level=debug msg="new websocket client" Feb 24 01:33:30 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket established Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09: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" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09:00" level=info msg="connected to ap-gae2.spotify.com:443" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09:00" level=debug msg="completed challenge" Feb 24 01:33:30 volumio-ap-3 go-librespot[345]: time="2025-02-24T01:33:30+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:30 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:33:30 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:30 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:33 volumio-ap-3 volumio[970]: info: Getting Spotify volume Feb 24 01:33:33 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:33 volumio-ap-3 volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Feb 24 01:33:33 volumio-ap-3 volumio[970]: (node:970) 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: 7737) Feb 24 01:33:33 volumio-ap-3 volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 24 01:33:33 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:33:33 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:33 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:33 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:34 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:34 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23053. Feb 24 01:33:34 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:34 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: Librespot-go daemon starting... Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09:00" level=info msg="generated new device id: 3e3f0e2b9cd95e36044a3d8d2ab1dfd91b2e18d0" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09: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]" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09: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]" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09: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]" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09:00" level=debug msg="zeroconf server listening on port 35339" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09:00" level=debug msg="obtained new client token: AACjlFAP++KCIMVoDAuKSG/ndzDrIGug0bV/Ci9iH0bZy8F8yCs1YRa9uyRwUwNpZwgPe4Ud60HoX2dA/CWx2djaO7oAWNlkkDr9fJREhvrCUW+uyeYgXKHnms3l0k2Szxt/0mMwgFWdQHEqi2kNMKqTg8Zfoj3zcwVgqnD/Z4k4MVteFpsuqRJJUxd2kiNBJjfzCeCS8sQhIs7QtbpPbJ1Ud33ML8kg/hLeZ/nSxv9eMx9hCyojeI7Z1UJHCn7l" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:34 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:34+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:35 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:35+09:00" level=debug msg="completed challenge" Feb 24 01:33:35 volumio-ap-3 go-librespot[353]: time="2025-02-24T01:33:35+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:35 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:35 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:36 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:36 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:38 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:38 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23054. Feb 24 01:33:38 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:38 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: Librespot-go daemon starting... Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09:00" level=info msg="generated new device id: dfbec47c049b62b35b0a8507987ebca72906b21f" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09: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]" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09: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]" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09: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]" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09:00" level=debug msg="zeroconf server listening on port 33613" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09:00" level=debug msg="obtained new client token: AAAs+ZZVK5FAJ2PQBLnjCBU5n1eDUTb51Gz/DM/7QNjX+SDqs+HKRJ4+z0ctJZrZ3kcSqXONCbRqcSrlLioQspg+wxNf7j4eeYairKZFt2zUxciRLb5utz74j+5/fhFoDntE52fvKImrJyOxEtQX/+yg5W5Ieh5nczWcWRSxIaDJWcG9Cn8xTePnCAALDMVw7/vgzvOYN/Yn68pwCT6b+ox4ZQ0lvCaqK9+AbXE+Y7Dy52xEsOa3GU+dIMYWhcVh" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:38 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:38+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:39 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:39+09:00" level=debug msg="completed challenge" Feb 24 01:33:39 volumio-ap-3 go-librespot[363]: time="2025-02-24T01:33:39+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:39 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:39 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:39 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:39 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:42 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:42 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23055. Feb 24 01:33:42 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:42 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: Librespot-go daemon starting... Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09:00" level=info msg="generated new device id: 75a67ce4d48970443c5638db5f76bb5137c7ffaa" Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09: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]" Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09: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]" Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09: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]" Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09:00" level=debug msg="zeroconf server listening on port 34143" Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09:00" level=debug msg="obtained new client token: AABKQgzufYhubAFdGOhueGzVvnJOI62PXlbiI7g68Vr0tZfpSZd1bojk6IB12VH2VURFCFPdD2sxXMynftbGw4V7LgiO/1mloWzPlLr2HyjU31QASaf5ELanZTpB1qFfYnKDsPTcxdAee5PcdgYlzvx0hGz+ST/1TfwEGTnzeVYGeK5Oa4m/tEMyF43xtBR02/yewI1XSLMgtVsfSZEAIgo2hBNyJgALzJtQNE26kI3LyRNXDcEnM9j8enog76f4" Feb 24 01:33:42 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09:00" level=debug msg="new websocket client" Feb 24 01:33:42 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket established Feb 24 01:33:42 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:42+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:43 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:43+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:43 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:43+09:00" level=debug msg="completed challenge" Feb 24 01:33:43 volumio-ap-3 go-librespot[393]: time="2025-02-24T01:33:43+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:43 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:43 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:43 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:33:45 volumio-ap-3 volumio[970]: info: Getting Spotify volume Feb 24 01:33:45 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:45 volumio-ap-3 volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Feb 24 01:33:45 volumio-ap-3 volumio[970]: (node:970) 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: 7738) Feb 24 01:33:45 volumio-ap-3 volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 24 01:33:45 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:33:45 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:46 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:46 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:46 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:46 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23056. Feb 24 01:33:46 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:46 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:46 volumio-ap-3 go-librespot[406]: Librespot-go daemon starting... Feb 24 01:33:46 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:46+09:00" level=info msg="generated new device id: 426791179b8bd4e88088cf7169feff5777fc3416" Feb 24 01:33:46 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:46+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09: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]" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09: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]" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09: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]" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09:00" level=debug msg="zeroconf server listening on port 38129" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09:00" level=debug msg="obtained new client token: AADe3TKKHht2kpQetKKVY6VXj2Le7JBNX27J070Uk995tsG+wjf8m7llb+Azzw+DEZ6mxcmVj2yy8ncFbBLC4sO97SR1GH1j8XzBDxi6ZbwWrJQo2LOEDxLAQJ6abmDWHF6wBGT353OMtjb/DGKa+n/MUpS8zvgXHqU/P49smXP+jysYtiwBKEOKi19rcLSFrll1QHbnJM47I3iaXYOgN/6dWesFnzKP18Ewd1KPtunQBaDbsW77/saQnnJOWA==" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09:00" level=debug msg="completed challenge" Feb 24 01:33:47 volumio-ap-3 go-librespot[406]: time="2025-02-24T01:33:47+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:47 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:47 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:49 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:49 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:50 volumio-ap-3 volumio[970]: info: Clearing queue after UPNP request Feb 24 01:33:51 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:51 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23057. Feb 24 01:33:51 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:51 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: Librespot-go daemon starting... Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09:00" level=info msg="generated new device id: f1b7518a8049eafbbe69ba4071fa63e4733d70ab" Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:51 volumio-ap-3 volumio[970]: info: CoreStateMachine::ClearQueue Feb 24 01:33:51 volumio-ap-3 volumio[970]: info: CoreStateMachine::stop Feb 24 01:33:51 volumio-ap-3 volumio[970]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 01:33:51 volumio-ap-3 volumio[970]: info: CorePlayQueue::clearPlayQueue Feb 24 01:33:51 volumio-ap-3 volumio[970]: info: CorePlayQueue::saveQueue Feb 24 01:33:51 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioPushState Feb 24 01:33:51 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioPushQueue Feb 24 01:33:51 volumio-ap-3 volumio[970]: error: Upnp client error: Error: This socket has been ended by the other party Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09: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]" Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09: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]" Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09: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]" Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09:00" level=debug msg="zeroconf server listening on port 38183" Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09:00" level=debug msg="obtained new client token: AAABoDvnyUGxqSXnEv3fKhtyMnSlSfMSB4T/zo3XPfIpYMa/lHmKzqY3QVl42nV9+sYKp/he1P3KaG1G/sxhGkhX2lhd02WAbtO2u3TqJYHRvChu0FeLyd1N9q9KR5T60GPnlBpi69m8L8v7y5gADTu0eQhTTMcbqjJ1IprhztKcHfU4PwpkP6IS4TYWTxqxrlv0bHPNqhqLEJjfVdUF9RSOXf4iP4V0iQnImPa25BqnTTB8KsfkaQEVyYFfuyQF" Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09:00" level=info msg="connected to ap-gae2.spotify.com:4070" Feb 24 01:33:51 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:51+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:52 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:52+09:00" level=debug msg="completed challenge" Feb 24 01:33:52 volumio-ap-3 go-librespot[431]: time="2025-02-24T01:33:52+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:52 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:52 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:52 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:52 volumio-ap-3 volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:52 volumio-ap-3 volumio[970]: info: Starting UPNP Playback Feb 24 01:33:52 volumio-ap-3 volumio[970]: info: Preparing playback through UPNP Feb 24 01:33:52 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:33:52 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:52 volumio-ap-3 volumio[970]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Feb 24 01:33:53 volumio-ap-3 volumio[970]: ---------------------------- MPD announces system playlist update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Ignoring MPD Status Update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Feb 24 01:33:53 volumio-ap-3 volumio[970]: ---------------------------- MPD announces system playlist update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Ignoring MPD Status Update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: ------------------------------ 7ms Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: ------------------------------ 2ms Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Feb 24 01:33:53 volumio-ap-3 volumio[970]: ---------------------------- MPD announces system playlist update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Ignoring MPD Status Update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Feb 24 01:33:53 volumio-ap-3 volumio[970]: ---------------------------- MPD announces system playlist update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Ignoring MPD Status Update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: ------------------------------ 2ms Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: ------------------------------ 2ms Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Feb 24 01:33:53 volumio-ap-3 volumio[970]: ---------------------------- MPD announces system playlist update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Ignoring MPD Status Update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Feb 24 01:33:53 volumio-ap-3 volumio[970]: ---------------------------- MPD announces system playlist update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: Ignoring MPD Status Update Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: ------------------------------ 2ms Feb 24 01:33:53 volumio-ap-3 volumio[970]: info: ------------------------------ 2ms Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: Feb 24 01:33:54 volumio-ap-3 volumio[970]: ---------------------------- MPD announces state update: player Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: ControllerMpd::getState Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::sendMpdCommand status Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: Feb 24 01:33:54 volumio-ap-3 volumio[970]: ---------------------------- MPD announces state update: player Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: sendMpdCommand status took 6 milliseconds Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: ControllerMpd::getState Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::sendMpdCommand status Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::parseState Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: sendMpdCommand status took 5 milliseconds Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::parseState Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::parseTrackInfo Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: ControllerMpd::pushState Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CoreCommandRouter::servicePushState Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: In UPNP mode Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":44.1,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"playlist.m3u8","artist":null,"album":null,"uri":"https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/playlist.m3u8","trackType":"m3u8"} Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: CURRENT POSITION 0 Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CoreStateMachine::syncState stateService play Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CoreStateMachine::syncState currentStatus stop Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: ------------------------------ 24ms Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: sendMpdCommand playlistinfo took 10 milliseconds Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: ControllerMpd::parseTrackInfo Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: ControllerMpd::pushState Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CoreCommandRouter::servicePushState Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: In UPNP mode Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: STATE SERVICE {"status":"play","position":1,"seek":0,"duration":0,"samplerate":44.1,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"playlist.m3u8","artist":null,"album":null,"uri":"https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/playlist.m3u8","trackType":"m3u8"} Feb 24 01:33:54 volumio-ap-3 volumio[970]: verbose: CURRENT POSITION 0 Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CoreStateMachine::syncState stateService play Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CoreStateMachine::syncState currentStatus play Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: Received an update from plugin. extracting info from payload Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CoreStateMachine::pushState Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:54 volumio-ap-3 volumio[970]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Feb 24 01:33:54 volumio-ap-3 volumio[970]: info: ------------------------------ 26ms Feb 24 01:33:55 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 01:33:55 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23058. Feb 24 01:33:55 volumio-ap-3 systemd[1]: Stopped go-librespot Daemon. Feb 24 01:33:55 volumio-ap-3 systemd[1]: Started go-librespot Daemon. Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: Librespot-go daemon starting... Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09:00" level=info msg="generated new device id: 13d2c925c9ae6da1e4e0edd823bbc296ebdc6f63" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09:00" level=debug msg="stored credentials found for 0p5pdobhwlkcud2dbj5tj8jsj" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09: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]" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09: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]" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09: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]" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09:00" level=debug msg="zeroconf server listening on port 42041" Feb 24 01:33:55 volumio-ap-3 volumio[970]: info: Initializing connection to go-librespot Websocket Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09:00" level=debug msg="new websocket client" Feb 24 01:33:55 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket established Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09:00" level=debug msg="obtained new client token: AAC3L96go0JDKlPTXibQHqeyyyuhpesOpiG5nWP7KkHHkStRXMMYogZ77PXL48nnaCpEyHtI/JtkMt9LZmbThrpmhtNH/wnnmWz858n1WEsuta8YzioKSaCyUrWQE+0wPc3vtQsnk9vfUQQx/Qv5TOqk+n8elY/us5ebFvW7i+nC/Iv+wQyU7USs1c+hMbm9ktCclf6CAP2ehRD5Yh/JfeY47va0mGXUgRH4srb1iKlpEP8LESEQr0BViiuU9jtb" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09: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" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09:00" level=info msg="connected to ap-gae2.spotify.com:443" Feb 24 01:33:55 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:55+09:00" level=debug msg="completed keyexchange" Feb 24 01:33:56 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:56+09:00" level=debug msg="completed challenge" Feb 24 01:33:56 volumio-ap-3 go-librespot[448]: time="2025-02-24T01:33:56+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: TravelRestriction" Feb 24 01:33:56 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 01:33:56 volumio-ap-3 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 01:33:56 volumio-ap-3 volumio[970]: info: Connection to go-librespot Websocket closed Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: Feb 24 01:33:57 volumio-ap-3 volumio[970]: ---------------------------- MPD announces state update: player Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: ControllerMpd::getState Feb 24 01:33:57 volumio-ap-3 volumio[970]: verbose: ControllerMpd::sendMpdCommand status Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: sendMpdCommand status took 2 milliseconds Feb 24 01:33:57 volumio-ap-3 volumio[970]: verbose: ControllerMpd::parseState Feb 24 01:33:57 volumio-ap-3 volumio[970]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: sendMpdCommand playlistinfo took 2 milliseconds Feb 24 01:33:57 volumio-ap-3 volumio[970]: verbose: ControllerMpd::parseTrackInfo Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: ControllerMpd::pushState Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: CoreCommandRouter::servicePushState Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: CoreStateMachine::pushState Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:57 volumio-ap-3 volumio[970]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Feb 24 01:33:57 volumio-ap-3 volumio[970]: info: ------------------------------ 8ms Feb 24 01:33:58 volumio-ap-3 volumio[970]: info: Getting Spotify volume Feb 24 01:33:58 volumio-ap-3 volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 01:33:58 volumio-ap-3 volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Feb 24 01:33:58 volumio-ap-3 volumio[970]: (node:970) 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: 7739) Feb 24 01:33:58 volumio-ap-3 volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 24 01:33:58 volumio-ap-3 volumio[970]: info: CoreCommandRouter::volumioGetState Feb 24 01:33:58 volumio-ap-3 volumio[970]: info: CorePlayQueue::getTrack 0 Feb 24 01:33:58 volumio-ap-3 volumio[970]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 01:33:58 volumio-ap-3 volumio[970]: TypeError: Cannot read property 'name' of undefined Feb 24 01:33:58 volumio-ap-3 volumio[970]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Feb 24 01:33:58 volumio-ap-3 volumio[970]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Feb 24 01:33:58 volumio-ap-3 volumio[970]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Feb 24 01:33:58 volumio-ap-3 volumio[970]: at Socket.emit (events.js:315:20) Feb 24 01:33:58 volumio-ap-3 volumio[970]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Feb 24 01:33:58 volumio-ap-3 volumio[970]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Feb 24 01:33:58 volumio-ap-3 volumio[970]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 01:33:59 volumio-ap-3 sudo[470]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-24 01:32 Feb 24 01:33:59 volumio-ap-3 sudo[470]: 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="cc0042a1eab1cb7982711a1347e242f8947b54b6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="d316d397153fbb98c246d670c12f98a120b995a2" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 11 Jan 2025 10:58:50 AM CET" VOLUMIO_VERSION="3.788" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e6f1869148b01453dc48d3e2d79d1421"