-- Logs begin at Tue 2024-07-09 19:08:03 CST, end at Mon 2024-08-19 11:31:19 CST. -- Aug 19 11:30:00 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:00 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:00 volumio1 go-librespot[4671]: time="2024-08-19T11:30:00+08:00" level=debug msg="completed challenge" Aug 19 11:30:00 volumio1 go-librespot[4671]: time="2024-08-19T11:30:00+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:00 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:00 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:01 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:01 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:02 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:02 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:02 volumio1 volumio[3234]: info: MyVolumio login type: Token Aug 19 11:30:03 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:03 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46. Aug 19 11:30:03 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:03 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:03 volumio1 go-librespot[4687]: Librespot-go daemon starting... Aug 19 11:30:03 volumio1 go-librespot[4687]: time="2024-08-19T11:30:03+08:00" level=info msg="generated new device id: d842891223d815a15d7f98fcde961782d6af4e50" Aug 19 11:30:03 volumio1 go-librespot[4687]: time="2024-08-19T11:30:03+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:03 volumio1 go-librespot[4687]: time="2024-08-19T11:30:03+08:00" level=debug msg="obtained new client token: AACUM5HhD3yG5Jn/R5XABSZOyV52HtUMz81kiU/BsDSw2vdXMXzxd/+QcIo2WMYrl8/J7GdCA4nC39QRMs5xDAhWgAdYlmywNkvZ945soVMmf+QIrlSAOv3b61PhtbPN+FnaWNJklEW6B/gV813Bf1K//d5gn8Wlepj/KUccmx4o+vViy7AGWMP1Eqrc80a2cvH6Jn58RNWNCwzPvqHmbs8p3av/bLqS8gsFrmKbh2nyIAhvhYmf2L36+NLGwg==" Aug 19 11:30:04 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:04 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:04 volumio1 go-librespot[4687]: time="2024-08-19T11:30:04+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 19 11:30:04 volumio1 go-librespot[4687]: time="2024-08-19T11:30:04+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:04 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:04 volumio1 go-librespot[4687]: time="2024-08-19T11:30:04+08:00" level=debug msg="new websocket client" Aug 19 11:30:04 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:30:05 volumio1 go-librespot[4687]: time="2024-08-19T11:30:05+08:00" level=debug msg="completed challenge" Aug 19 11:30:05 volumio1 go-librespot[4687]: time="2024-08-19T11:30:05+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:05 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:05 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:05 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:30:06 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:06 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:07 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:30:07 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:07 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:30:07 volumio1 volumio[3234]: (node:3234) 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: 23) Aug 19 11:30:07 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 19 11:30:07 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:07 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:07 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:08 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:08 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:08 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:08 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:08 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:08 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 47. Aug 19 11:30:08 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:08 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:08 volumio1 go-librespot[4705]: Librespot-go daemon starting... Aug 19 11:30:08 volumio1 go-librespot[4705]: time="2024-08-19T11:30:08+08:00" level=info msg="generated new device id: 62cd3b143e11aa97be1b169a8ea8466fb9e53d08" Aug 19 11:30:08 volumio1 go-librespot[4705]: time="2024-08-19T11:30:08+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:08 volumio1 go-librespot[4705]: time="2024-08-19T11:30:08+08:00" level=debug msg="obtained new client token: AAAwesT40+CgAjKGo4xbWaoH6y5X4bElAS01O1XyPoUcvBlPfOIXm8zPeJF7J7BsHiBLvjGHCpxY+CiuuvzN0dqMfEMbmagYRwckstjWjmLWFTAkN3jhzISnY9L1QHXN+VI5vHs/M7I9nIbdrr5Is+8FvVRUd7ysx2SVrPexQnYTMoIdOM0vExpmFS2QpVX4SDndn+92SMsUBeWitNTdjVLOhAbfeqE8DqlbpYDugwqT1KK4zrRhWBymFlV7WQ==" Aug 19 11:30:09 volumio1 go-librespot[4705]: time="2024-08-19T11:30:09+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 19 11:30:09 volumio1 go-librespot[4705]: time="2024-08-19T11:30:09+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:09 volumio1 go-librespot[4705]: time="2024-08-19T11:30:09+08:00" level=debug msg="completed challenge" Aug 19 11:30:09 volumio1 go-librespot[4705]: time="2024-08-19T11:30:09+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:09 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:09 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:10 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:10 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:11 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:11 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:12 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:12 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:12 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:12 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48. Aug 19 11:30:12 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:12 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:12 volumio1 go-librespot[4724]: Librespot-go daemon starting... Aug 19 11:30:12 volumio1 go-librespot[4724]: time="2024-08-19T11:30:12+08:00" level=info msg="generated new device id: 21263ebd6a21936230a5074d7f7255f23720930d" Aug 19 11:30:12 volumio1 go-librespot[4724]: time="2024-08-19T11:30:12+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:13 volumio1 go-librespot[4724]: time="2024-08-19T11:30:13+08:00" level=debug msg="obtained new client token: AAC1lgbffE7wxcLwJIJI1rqwSA8rZbnCM/hNqPWjsit3PJ5iJL/GqWCdb5DhWHehi2i45d8JhA0zTSyjU+4NHXDB7mnqCvdX86O0+6m+27UvnoweBCrHe8WA0lBuz3OnKrxvBWtZxvw4HMLmfzO0w+l4nlj8gcrvpEPfjPJ8XP3ti13V6r7lb5jq/ZuSZ5oEXq4KEmInEaTEo+muWWgzOx5PGAAiusM4b1goxFL1q7ayj3AAkIDzEc/yi1DFLg==" Aug 19 11:30:13 volumio1 go-librespot[4724]: time="2024-08-19T11:30: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 19 11:30:14 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:14 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:14 volumio1 go-librespot[4724]: time="2024-08-19T11:30:14+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:14 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:14 volumio1 go-librespot[4724]: time="2024-08-19T11:30:14+08:00" level=debug msg="new websocket client" Aug 19 11:30:14 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:30:14 volumio1 go-librespot[4724]: time="2024-08-19T11:30:14+08:00" level=debug msg="completed challenge" Aug 19 11:30:14 volumio1 go-librespot[4724]: time="2024-08-19T11:30:14+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:14 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:14 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:14 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:30:16 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:16 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:17 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:30:17 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:17 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:30:17 volumio1 volumio[3234]: (node:3234) 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: 24) Aug 19 11:30:17 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 19 11:30:17 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:17 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:17 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:17 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:17 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:17 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:17 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49. Aug 19 11:30:17 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:17 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:17 volumio1 go-librespot[4743]: Librespot-go daemon starting... Aug 19 11:30:17 volumio1 go-librespot[4743]: time="2024-08-19T11:30:17+08:00" level=info msg="generated new device id: 3915ef2216b81ec9ee9f0c664c9f25c28b49014f" Aug 19 11:30:17 volumio1 go-librespot[4743]: time="2024-08-19T11:30:17+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:18 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:18 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:18 volumio1 go-librespot[4743]: time="2024-08-19T11:30:18+08:00" level=debug msg="obtained new client token: AAB8bX3tt2HUN0DgyRualuzafkOY148cNRPCg0d8bZcGcRVCS2RkYAa/gkggAdFHNTGHkIA1GwcIWpRtXchFWGy7hjpbuqvia43vnGJE9leodp6iRDaRMfjG6twNAB7cBJshITaJwxiZIWzUhsPmMPNOM2rV5tPi09kHijq9M4ac9AxNz4IAzK51a4ExDeqESQa4tb0ep0sWzEs4usYacBT3+YwrH0zSXNRpzaqy/EO7+9/4tTHLUAPKKXXG/w==" Aug 19 11:30:18 volumio1 go-librespot[4743]: time="2024-08-19T11:30: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-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 19 11:30:18 volumio1 go-librespot[4743]: time="2024-08-19T11:30:18+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:19 volumio1 go-librespot[4743]: time="2024-08-19T11:30:19+08:00" level=debug msg="completed challenge" Aug 19 11:30:19 volumio1 go-librespot[4743]: time="2024-08-19T11:30:19+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:19 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:19 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:20 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:20 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:20 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:20 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:22 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:22 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:22 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:22 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50. Aug 19 11:30:22 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:22 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:22 volumio1 go-librespot[4760]: Librespot-go daemon starting... Aug 19 11:30:22 volumio1 go-librespot[4760]: time="2024-08-19T11:30:22+08:00" level=info msg="generated new device id: a0ad2499b9867f55a42120bbd5cce06ad526802b" Aug 19 11:30:22 volumio1 go-librespot[4760]: time="2024-08-19T11:30:22+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:23 volumio1 go-librespot[4760]: time="2024-08-19T11:30:23+08:00" level=debug msg="obtained new client token: AAA229e/NIlzaPuFMDEB9tdWVJ+QTMA/ry3JshtTuyckbYvF/TR5rC5wii0Qy0A7QlImmouqBQXr4rWIi+P606yZ7//JNB09r6izVfYd4WzZpv4535PpWDgVSI6zWt9LcV1+6LLgGHCAjNygsBKgiIsV7GPz6YPnro5tZC2IX6QSwIveo56UHxdBWTM5hUU2WpQ5yYYgwH0IYVvNU7JNlWT/IEaLyLQIyR2n1hTqJ0Osax7g9Lu7mmDPS1OQ/Q==" Aug 19 11:30:23 volumio1 go-librespot[4760]: time="2024-08-19T11:30: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 19 11:30:23 volumio1 go-librespot[4760]: time="2024-08-19T11:30:23+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:23 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:23 volumio1 go-librespot[4760]: time="2024-08-19T11:30:23+08:00" level=debug msg="new websocket client" Aug 19 11:30:23 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:30:24 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:24 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:24 volumio1 go-librespot[4760]: time="2024-08-19T11:30:24+08:00" level=debug msg="completed challenge" Aug 19 11:30:24 volumio1 go-librespot[4760]: time="2024-08-19T11:30:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:24 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:24 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:24 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:30:26 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:26 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:26 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:30:26 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:26 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:30:26 volumio1 volumio[3234]: (node:3234) 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: 25) Aug 19 11:30:26 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 19 11:30:26 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:26 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:27 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:27 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:27 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:27 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:27 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 51. Aug 19 11:30:27 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:27 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:27 volumio1 go-librespot[4779]: Librespot-go daemon starting... Aug 19 11:30:27 volumio1 go-librespot[4779]: time="2024-08-19T11:30:27+08:00" level=info msg="generated new device id: 1c757cfff4e234d9ab6d5bb5374967b51d0d7bcc" Aug 19 11:30:27 volumio1 go-librespot[4779]: time="2024-08-19T11:30:27+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:27 volumio1 go-librespot[4779]: time="2024-08-19T11:30:27+08:00" level=debug msg="obtained new client token: AACT7TN48ir3ofe6c88Euj/KA0bGyU2z9vviNfkR5FeQ9/crMDdLRRJIqkMSLV3AHf1PECwpzxzWRS85A61a/irguC+KX4uEf59dl8tsjiZUNS0xU6xieRcntBXPh/QEDV0nwgpcRvujgDqa2zRElnn5fnpt/uSYq8lbURgXpEF5RkFvtDD4bgN7H4S4wuiIYJTjdKQ2QbLF6cvdxXJyxgzQxVYqovx4M5zPuU0lgyyK7XpABwzyQ2ky4tI9dQ==" Aug 19 11:30:28 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:28 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:28 volumio1 go-librespot[4779]: time="2024-08-19T11:30:28+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]" Aug 19 11:30:28 volumio1 go-librespot[4779]: time="2024-08-19T11:30:28+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:29 volumio1 go-librespot[4779]: time="2024-08-19T11:30:29+08:00" level=debug msg="completed challenge" Aug 19 11:30:29 volumio1 go-librespot[4779]: time="2024-08-19T11:30:29+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:29 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:29 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:30 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:30 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:30 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:30 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:32 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:32 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:32 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:32 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 52. Aug 19 11:30:32 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:32 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:32 volumio1 go-librespot[4797]: Librespot-go daemon starting... Aug 19 11:30:32 volumio1 go-librespot[4797]: time="2024-08-19T11:30:32+08:00" level=info msg="generated new device id: 6b995a849612ef35f127e7dec3cb0d1341664570" Aug 19 11:30:32 volumio1 go-librespot[4797]: time="2024-08-19T11:30:32+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:32 volumio1 volumio[3234]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 19 11:30:32 volumio1 volumio[3234]: info: Retrying Login Due to Network Error Aug 19 11:30:32 volumio1 go-librespot[4797]: time="2024-08-19T11:30:32+08:00" level=debug msg="obtained new client token: AADjSPadvu+mjr68qS71VK1fumMGSzZaGrSvEb8WckABwCgDe/3PUrLs5+g6yHeOs/wy37q6grgLsXWHr1OtlR2cL+ZCIKS1kR4ZDUiR7mf7bHUA8A9XdHSearUX7C6SvC7BZRClCVqOjX+Zenfb0CGHiDyl161cEqHxBzROGrw2eYOspRsgjd4/2YqDf2m5nfdlllBIH/j4Y7RhFvh3WO8+Yy7bOFz7BFVTpkHjHC4o1HxBIo3MAqW0ud0dIw==" Aug 19 11:30:33 volumio1 go-librespot[4797]: time="2024-08-19T11:30:33+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]" Aug 19 11:30:33 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:33 volumio1 go-librespot[4797]: time="2024-08-19T11:30:33+08:00" level=debug msg="new websocket client" Aug 19 11:30:33 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:30:33 volumio1 go-librespot[4797]: time="2024-08-19T11:30:33+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:33 volumio1 go-librespot[4797]: time="2024-08-19T11:30:33+08:00" level=debug msg="completed challenge" Aug 19 11:30:34 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:34 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:34 volumio1 go-librespot[4797]: time="2024-08-19T11:30:34+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:34 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:34 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:34 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:30:36 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:36 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:36 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:30:36 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:36 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:30:36 volumio1 volumio[3234]: (node:3234) 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: 26) Aug 19 11:30:36 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 19 11:30:36 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:36 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:36 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:37 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:37 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:37 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:37 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 53. Aug 19 11:30:37 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:37 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:37 volumio1 go-librespot[4816]: Librespot-go daemon starting... Aug 19 11:30:37 volumio1 go-librespot[4816]: time="2024-08-19T11:30:37+08:00" level=info msg="generated new device id: a7279b692236ff271450384fd1ea91ecc3727b88" Aug 19 11:30:37 volumio1 go-librespot[4816]: time="2024-08-19T11:30:37+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:37 volumio1 go-librespot[4816]: time="2024-08-19T11:30:37+08:00" level=debug msg="obtained new client token: AAC4bgOfzWTmHNE8YxcTdXTs96zj4PvIXtDphkaSqmu/asiDeAMRSNERvIZTdocS9SoPJChf9LY36OwK5+ZB87Uzd7HXIxT2LqpUfyYiFJ6oupyUUaZLU8Fo67jpJuwfb/lPwxreXhotfKPQRArnZ3ykFCOKIsuhnj+N5mWvOY1jUmTaI8ClO+nqfY47m9/PbVm95yzbgakQKvRbOx+L/vMT+hzpmikGP6obH7lhvdAxh4hHqPHd1Om61sbIBg==" Aug 19 11:30:38 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:38 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:38 volumio1 go-librespot[4816]: time="2024-08-19T11:30:38+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]" Aug 19 11:30:38 volumio1 go-librespot[4816]: time="2024-08-19T11:30:38+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:38 volumio1 go-librespot[4816]: time="2024-08-19T11:30:38+08:00" level=debug msg="completed challenge" Aug 19 11:30:38 volumio1 go-librespot[4816]: time="2024-08-19T11:30:38+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:38 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:38 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:40 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:40 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:40 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:40 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:41 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:41 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 54. Aug 19 11:30:41 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:41 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:41 volumio1 go-librespot[4870]: Librespot-go daemon starting... Aug 19 11:30:41 volumio1 go-librespot[4870]: time="2024-08-19T11:30:41+08:00" level=info msg="generated new device id: 12b2300ae2b23dbc33e393ac3ad1bdf9b59eacb1" Aug 19 11:30:41 volumio1 go-librespot[4870]: time="2024-08-19T11:30:41+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:42 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:42 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:42 volumio1 go-librespot[4870]: time="2024-08-19T11:30:42+08:00" level=debug msg="obtained new client token: AABdLWaiWg6bvY2CIVXNKVX2h5Vcp5Pn1PMhwMTBbA4kpvwqOp7yz44YK+Ehmyf2EYhBCSOK64cQav5YwyHgvNUt0RsRM36mUn/bHsow7QglsUFyRxFrsV5zBqHEOYCROibl40iAqYo+4014S8TaibvZhpyCMvgYhdtMEcN7M/GR50C5IGvdkk6V/BuBln58jdPzaAJkFJesbsUSXhALdiaEulZdkn/yxDCik4IYjCTYWlU1IOQrJDVHX35sAQ==" Aug 19 11:30:42 volumio1 go-librespot[4870]: time="2024-08-19T11:30:42+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]" Aug 19 11:30:42 volumio1 volumio[3234]: info: MyVolumio login type: Token Aug 19 11:30:42 volumio1 go-librespot[4870]: time="2024-08-19T11:30:42+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:43 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:43 volumio1 go-librespot[4870]: time="2024-08-19T11:30:43+08:00" level=debug msg="new websocket client" Aug 19 11:30:43 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:30:43 volumio1 go-librespot[4870]: time="2024-08-19T11:30:43+08:00" level=debug msg="completed challenge" Aug 19 11:30:43 volumio1 go-librespot[4870]: time="2024-08-19T11:30:43+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:43 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:43 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:43 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:30:44 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:44 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:46 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:46 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:46 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:30:46 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:46 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:30:46 volumio1 volumio[3234]: (node:3234) 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: 27) Aug 19 11:30:46 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 19 11:30:46 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:46 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:46 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:46 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:46 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:46 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:46 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55. Aug 19 11:30:46 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:46 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:46 volumio1 go-librespot[4889]: Librespot-go daemon starting... Aug 19 11:30:46 volumio1 go-librespot[4889]: time="2024-08-19T11:30:46+08:00" level=info msg="generated new device id: fd263be3800e507bebec2aafda87c2fa9352bade" Aug 19 11:30:46 volumio1 go-librespot[4889]: time="2024-08-19T11:30:46+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:47 volumio1 go-librespot[4889]: time="2024-08-19T11:30:47+08:00" level=debug msg="obtained new client token: AAByr/XburjTgpwjnzDFfnCOBmrZnAMDKNR8wiVS6pHoi1Toe0s3NNDTKbTm19khTAI3hQw+LdGKfvcLUer94VUdtKFAuEggagt1/S0Vu8u/0TCmoYlkV4Cv0M+i8gxRy6MAAH4h1WX33lvgqzp4KX+Q4aQ/Humw62gKV7eI8DIx+DPXS6Yus0xyk4/gmikDUoeG2VIjRmglzckF8XrmTYTFdjypCA2ZRWkSrsxNqDnZ3YDfYaNJuY+GajA=" Aug 19 11:30:47 volumio1 go-librespot[4889]: time="2024-08-19T11:30:47+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]" Aug 19 11:30:47 volumio1 go-librespot[4889]: time="2024-08-19T11:30:47+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:47 volumio1 volumio[3234]: verbose: New Socket.io Connection to 192.168.1.111 from 192.168.1.82 UA: okhttp/4.9.2 Engine version: 3 Transport: websocket Total Clients: 7 Aug 19 11:30:47 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:47 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:47 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 19 11:30:47 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 19 11:30:47 volumio1 go-librespot[4889]: time="2024-08-19T11:30:47+08:00" level=debug msg="completed challenge" Aug 19 11:30:48 volumio1 go-librespot[4889]: time="2024-08-19T11:30:48+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:48 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:48 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:48 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:48 volumio1 volumio[3234]: verbose: New Socket.io Connection to 192.168.1.111 from 192.168.1.82 UA: okhttp/4.9.2 Engine version: 3 Transport: polling Total Clients: 8 Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetVisibleSources Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:48 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 19 11:30:48 volumio1 volumio[3234]: info: Received Get System Info Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 19 11:30:48 volumio1 volumio[3234]: info: Discovery: Getting this device information Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:48 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:48 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:48 volumio1 volumio[3234]: info: Listing playlists Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Aug 19 11:30:48 volumio1 volumio[3234]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 19 11:30:49 volumio1 volumio[3234]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 19 11:30:49 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:49 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:50 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetQueue Aug 19 11:30:50 volumio1 volumio[3234]: info: CoreStateMachine::getQueue Aug 19 11:30:50 volumio1 volumio[3234]: info: CorePlayQueue::getQueue Aug 19 11:30:50 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:50 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:50 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 19 11:30:50 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 19 11:30:50 volumio1 volumio[3234]: info: Discovery: Getting this device information Aug 19 11:30:50 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:50 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:50 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 19 11:30:51 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:51 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56. Aug 19 11:30:51 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:51 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:51 volumio1 go-librespot[4905]: Librespot-go daemon starting... Aug 19 11:30:51 volumio1 go-librespot[4905]: time="2024-08-19T11:30:51+08:00" level=info msg="generated new device id: 46ffa0de166a3c93b27bffe574e535500f552352" Aug 19 11:30:51 volumio1 go-librespot[4905]: time="2024-08-19T11:30:51+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:51 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 19 11:30:51 volumio1 volumio[3234]: info: CURURI: music-library Aug 19 11:30:51 volumio1 volumio[3234]: info: Preload queue cleared Aug 19 11:30:51 volumio1 go-librespot[4905]: time="2024-08-19T11:30:51+08:00" level=debug msg="obtained new client token: AABdRen6agG3idmjNWeewPgSeH7JHkAIOYKYKUb5h6YFeTF6/q3uQdyBvWabT9mLtKR/JCGzcYLJrdW8MCK9JThgZjhMPwKLa4QHzs+Al/XATaRzr1RRdSwApD12IfFULQtr13czGTP5DWwey1PlLxiAVcomrtii7nrfRwl4ZlqiAUTHNNwp2onfwc4+mws/LtDcUoOhv1IN/ULWff2Y9rINbZhzLk6hXPUS3V55AxdzjnoWb18IqXX2UuBSNA==" Aug 19 11:30:51 volumio1 go-librespot[4905]: time="2024-08-19T11:30:51+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 19 11:30:52 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:52 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:52 volumio1 go-librespot[4905]: time="2024-08-19T11:30:52+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:52 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 19 11:30:52 volumio1 volumio[3234]: info: CURURI: music-library/USB Aug 19 11:30:52 volumio1 volumio[3234]: info: Preload queue cleared Aug 19 11:30:52 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:52 volumio1 go-librespot[4905]: time="2024-08-19T11:30:52+08:00" level=debug msg="new websocket client" Aug 19 11:30:52 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:30:52 volumio1 go-librespot[4905]: time="2024-08-19T11:30:52+08:00" level=debug msg="completed challenge" Aug 19 11:30:53 volumio1 go-librespot[4905]: time="2024-08-19T11:30:53+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:53 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:53 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:53 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:30:53 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 19 11:30:53 volumio1 volumio[3234]: info: CURURI: music-library/USB/900B-7EA1 Aug 19 11:30:53 volumio1 volumio[3234]: info: Preload queue cleared Aug 19 11:30:54 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:54 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:54 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Aug 19 11:30:54 volumio1 volumio[3234]: info: CURURI: music-library/USB/900B-7EA1/2024 Aug 19 11:30:54 volumio1 volumio[3234]: info: Preload queue cleared Aug 19 11:30:55 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:30:55 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:55 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:30:55 volumio1 volumio[3234]: (node:3234) 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: 28) Aug 19 11:30:55 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 19 11:30:55 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:55 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:55 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:56 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:56 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:56 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:56 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:56 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:30:56 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57. Aug 19 11:30:56 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:30:56 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:30:56 volumio1 go-librespot[4924]: Librespot-go daemon starting... Aug 19 11:30:56 volumio1 go-librespot[4924]: time="2024-08-19T11:30:56+08:00" level=info msg="generated new device id: 0dedaa4e98115e3c6feea2ae516d3d5963a69d90" Aug 19 11:30:56 volumio1 go-librespot[4924]: time="2024-08-19T11:30:56+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:30:56 volumio1 go-librespot[4924]: time="2024-08-19T11:30:56+08:00" level=debug msg="obtained new client token: AACohkmaDGzjZsrqkAFqecGlbYhXJ+fFSj479nQpzkDqJ8BEV9WCW/49ZXh5/OFG2CV9vNmy4WxhgxLBwfCSo4QFuVT2JlG+DVye8Cyxojz/ULDgsm5VyGEwTqtBjuyORcnCi09lSxWaRfvqYRsrvLxjTvpnSAMoAHYYsryhAqUQPLJS7VZs/00RG1UZVcs7FwME3bv0T7lOo9d+mfUgIdkdv/48WVGtUOe5T8rRQasWQZeTTf95kW+uNpBg/A==" Aug 19 11:30:56 volumio1 go-librespot[4924]: time="2024-08-19T11:30:56+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]" Aug 19 11:30:57 volumio1 go-librespot[4924]: time="2024-08-19T11:30:57+08:00" level=debug msg="completed keyexchange" Aug 19 11:30:57 volumio1 go-librespot[4924]: time="2024-08-19T11:30:57+08:00" level=debug msg="completed challenge" Aug 19 11:30:58 volumio1 go-librespot[4924]: time="2024-08-19T11:30:58+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:30:58 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:30:58 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:58 volumio1 volumio[3234]: info: Preload queue cleared Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::ClearQueue Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::stPlaybackTimer Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::updateTrackBlock Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrackBlock Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::serviceStop Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 1 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::serviceStop Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::stop Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::clearPlayQueue Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::saveQueue Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushQueue Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::addQueueItems Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::addQueueItems Aug 19 11:30:58 volumio1 volumio[3234]: info: Preload queue cleared Aug 19 11:30:58 volumio1 volumio[3234]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 19 11:30:58 volumio1 volumio[3234]: info: Using cached record of: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 19 11:30:58 volumio1 volumio[3234]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 19 11:30:58 volumio1 volumio[3234]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 19 11:30:58 volumio1 volumio[3234]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 19 11:30:58 volumio1 volumio[3234]: info: Using cached record of: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 19 11:30:58 volumio1 volumio[3234]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 19 11:30:58 volumio1 volumio[3234]: info: Using cached record of: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 19 11:30:58 volumio1 volumio[3234]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 19 11:30:58 volumio1 volumio[3234]: info: Using cached record of: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 19 11:30:58 volumio1 volumio[3234]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 19 11:30:58 volumio1 volumio[3234]: info: Using cached record of: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushQueue Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::saveQueue Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::updateTrackBlock Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrackBlock Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPlay Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::play index 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::play index undefined Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::startPlaybackTimer Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::clearAddPlayTracks USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand stop Aug 19 11:30:58 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:58 volumio1 volumio[3234]: info: Aug 19 11:30:58 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:58 volumio1 volumio[3234]: info: sendMpdCommand stop took 62 milliseconds Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:58 volumio1 volumio[3234]: info: sendMpdCommand stop took 19 milliseconds Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand clear Aug 19 11:30:58 volumio1 volumio[3234]: info: Aug 19 11:30:58 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:58 volumio1 volumio[3234]: info: Aug 19 11:30:58 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:58 volumio1 volumio[3234]: info: Aug 19 11:30:58 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:58 volumio1 volumio[3234]: info: Aug 19 11:30:58 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:58 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:58 volumio1 volumio[3234]: info: sendMpdCommand status took 22 milliseconds Aug 19 11:30:58 volumio1 volumio[3234]: info: sendMpdCommand clear took 21 milliseconds Aug 19 11:30:58 volumio1 volumio[3234]: info: sendMpdCommand status took 19 milliseconds Aug 19 11:30:58 volumio1 volumio[3234]: info: sendMpdCommand status took 16 milliseconds Aug 19 11:30:58 volumio1 volumio[3234]: info: sendMpdCommand status took 13 milliseconds Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand add "USB/900B-7EA1/2024/ZABO-Drown.FLAC" Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:58 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 19 11:30:58 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: No code Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 19 11:30:58 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: No code Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 19 11:30:58 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus stop Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:58 volumio1 volumio[3234]: info: No code Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:58 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:58 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 211ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 211ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 208ms Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:59 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:59 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:59 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:59 volumio1 volumio[3234]: error: updateQueue error: null Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:59 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 217ms Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 211 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand add "USB/900B-7EA1/2024/ZABO-Drown.FLAC" took 212 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 18ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 17ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 14ms Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand play Aug 19 11:30:59 volumio1 volumio[3234]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 245ms Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:59 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:59 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces system playlist update Aug 19 11:30:59 volumio1 volumio[3234]: info: Ignoring MPD Status Update Aug 19 11:30:59 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 63ms Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand play took 58 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 56ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 55ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 52ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/ZABO/Drown/329fcb02-95df-4a47-b750-78c2ece1bc62.png' Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 19 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 18 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 14 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 12 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 10 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: info: Aug 19 11:30:59 volumio1 volumio[3234]: ---------------------------- MPD announces state update: player Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::getState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand status Aug 19 11:30:59 volumio1 volumio[3234]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 19 11:30:59 volumio1 volumio[3234]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 19 11:30:59 volumio1 volumio[3234]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 19 11:30:59 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 76 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 75 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 75 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 75 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 74 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 70 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 67 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand status took 65 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseState Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus stop Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus play Aug 19 11:30:59 volumio1 volumio[3234]: info: Received an update from plugin. extracting info from payload Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus play Aug 19 11:30:59 volumio1 volumio[3234]: info: Received an update from plugin. extracting info from payload Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus play Aug 19 11:30:59 volumio1 volumio[3234]: info: Received an update from plugin. extracting info from payload Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus play Aug 19 11:30:59 volumio1 volumio[3234]: info: Received an update from plugin. extracting info from payload Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 172ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 332ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 327ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 331ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 330ms Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 238 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 239 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: info: sendMpdCommand playlistinfo took 239 milliseconds Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: verbose: ControllerMpd::parseTrackInfo Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus play Aug 19 11:30:59 volumio1 volumio[3234]: info: Received an update from plugin. extracting info from payload Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus play Aug 19 11:30:59 volumio1 volumio[3234]: info: Received an update from plugin. extracting info from payload Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ControllerMpd::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::servicePushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":185,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"777 Kbps","isStreaming":false,"title":"Drown","artist":"ZABO","album":"Drown","uri":"USB/900B-7EA1/2024/ZABO-Drown.FLAC","trackType":"FLAC"} Aug 19 11:30:59 volumio1 volumio[3234]: verbose: CURRENT POSITION 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState stateService play Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::syncState currentStatus play Aug 19 11:30:59 volumio1 volumio[3234]: info: Received an update from plugin. extracting info from payload Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreStateMachine::pushState Aug 19 11:30:59 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:30:59 volumio1 volumio[3234]: info: CoreCommandRouter::volumioPushState Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 450ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 448ms Aug 19 11:30:59 volumio1 volumio[3234]: info: ------------------------------ 445ms Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:30:59 volumio1 volumio[3234]: error: FusionDsp - WebSocket error: [object Object] Aug 19 11:30:59 volumio1 volumio[3234]: info: camilladsp spawned new process with pid 4942, instance 1, run: true Aug 19 11:30:59 volumio1 volumio[3234]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/ZABO/Drown/329fcb02-95df-4a47-b750-78c2ece1bc62.png' Aug 19 11:31:00 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:00 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:01 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:31:01 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 58. Aug 19 11:31:01 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:31:01 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:31:01 volumio1 go-librespot[4949]: Librespot-go daemon starting... Aug 19 11:31:01 volumio1 go-librespot[4949]: time="2024-08-19T11:31:01+08:00" level=info msg="generated new device id: 17864f4d87e7ed710b1e22669a1594c503bec3f5" Aug 19 11:31:01 volumio1 go-librespot[4949]: time="2024-08-19T11:31:01+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:31:01 volumio1 go-librespot[4949]: time="2024-08-19T11:31:01+08:00" level=debug msg="obtained new client token: AAC3JW7pH2VqsMJNT3LVPFnrKQkU2Qe0yBoTKiYC7csR1HRSYfWQC5mEMl4JN7ncnIyOFVBkPpViqD95/twQGDd9iv+IA1/TKNqm97x3uO8UFY4K4md0VVAzqNY5I8tVapjJDze0mt2PhJWK8OXjOH1vyiV1PceW1Z6CZLQ52Gi0nI0v35o8ZDSpUNI6uSVEZr5nMUKYuqihmOnny4R/6T+QMKtMHXBeB7/gVoiPN3jp8GfSp1C3HjTX1xpY4w==" Aug 19 11:31:01 volumio1 go-librespot[4949]: time="2024-08-19T11:31: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]" Aug 19 11:31:02 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:02 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:02 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:31:02 volumio1 go-librespot[4949]: time="2024-08-19T11:31:02+08:00" level=debug msg="completed keyexchange" Aug 19 11:31:02 volumio1 go-librespot[4949]: time="2024-08-19T11:31:02+08:00" level=debug msg="new websocket client" Aug 19 11:31:02 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:31:02 volumio1 go-librespot[4949]: time="2024-08-19T11:31:02+08:00" level=debug msg="completed challenge" Aug 19 11:31:02 volumio1 go-librespot[4949]: time="2024-08-19T11:31:02+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:31:02 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:31:02 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:31:02 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:31:04 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:04 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:05 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:31:05 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:31:05 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:31:05 volumio1 volumio[3234]: (node:3234) 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: 29) Aug 19 11:31:05 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Aug 19 11:31:05 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:05 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:05 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:31:05 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:31:05 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:31:05 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:31:05 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 59. Aug 19 11:31:05 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:31:05 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:31:05 volumio1 go-librespot[4970]: Librespot-go daemon starting... Aug 19 11:31:05 volumio1 go-librespot[4970]: time="2024-08-19T11:31:05+08:00" level=info msg="generated new device id: 04fea5da0b5b2475d36381409ede01219c24db46" Aug 19 11:31:05 volumio1 go-librespot[4970]: time="2024-08-19T11:31:05+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:31:06 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:06 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:06 volumio1 go-librespot[4970]: time="2024-08-19T11:31:06+08:00" level=debug msg="obtained new client token: AAAe93eXRqFjSUVV38qreTHifWxWqtVrNgaVlGKxy3rJTUd/NEc2YW/lDfp8sUvbK2Zgo5wa9PglK6g6YRlVI5IdiK21gv7BPvwnRdrxUh5MWDLHALzxqugaS2AtMUT4R2vKYb3H5aL+zM/rPd2fwW1/vSue5YNBi5XiYvnOU2O1n8jSsc1nZlkx5SMjIr/ZSx8OJhTMKPL4VhOogAAIE1c+tsf82eTZNHKx1WNQzdd+BB5vE5J9W27cJjFyUg==" Aug 19 11:31:06 volumio1 go-librespot[4970]: time="2024-08-19T11:31:06+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]" Aug 19 11:31:06 volumio1 go-librespot[4970]: time="2024-08-19T11:31:06+08:00" level=debug msg="completed keyexchange" Aug 19 11:31:07 volumio1 go-librespot[4970]: time="2024-08-19T11:31:07+08:00" level=debug msg="completed challenge" Aug 19 11:31:07 volumio1 go-librespot[4970]: time="2024-08-19T11:31:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:31:07 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:31:07 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:31:08 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:08 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:08 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:31:08 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:31:10 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:10 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:10 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:31:10 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 60. Aug 19 11:31:10 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:31:10 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:31:10 volumio1 go-librespot[4986]: Librespot-go daemon starting... Aug 19 11:31:10 volumio1 go-librespot[4986]: time="2024-08-19T11:31:10+08:00" level=info msg="generated new device id: 2fbd912635b016ce36bbe5289c92567a843a3747" Aug 19 11:31:10 volumio1 go-librespot[4986]: time="2024-08-19T11:31:10+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:31:11 volumio1 go-librespot[4986]: time="2024-08-19T11:31:11+08:00" level=debug msg="obtained new client token: AACzYmtl2LuxSRbMzjyl0HPvCbkFXqwC0NsXFLzbLtDKQoZqRWDmLnypCe9I1Ilc7fKDwSMuTKMR6w3O70OBu9Vu+4FbqdDCkkQfdwL0LBNRmfKM8nf1pomehbQjGj2T6b9oVFiXWKvp087E48yeza64K4fAxf8+z9erJIruaYQk5RyrVw2jvlUG58gjid9Z0ixytLfYvUGMukrbD+82pks6jNDXH87g7puD67kctm86uYJftS4+Bl4U/T8=" Aug 19 11:31:11 volumio1 go-librespot[4986]: time="2024-08-19T11:31:11+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 19 11:31:11 volumio1 go-librespot[4986]: time="2024-08-19T11:31:11+08:00" level=debug msg="completed keyexchange" Aug 19 11:31:11 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:31:11 volumio1 go-librespot[4986]: time="2024-08-19T11:31:11+08:00" level=debug msg="new websocket client" Aug 19 11:31:11 volumio1 volumio[3234]: info: Connection to go-librespot Websocket established Aug 19 11:31:12 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:12 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:12 volumio1 go-librespot[4986]: time="2024-08-19T11:31:12+08:00" level=debug msg="completed challenge" Aug 19 11:31:12 volumio1 go-librespot[4986]: time="2024-08-19T11:31:12+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:31:12 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:31:12 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:31:12 volumio1 volumio[3234]: info: Connection to go-librespot Websocket closed Aug 19 11:31:12 volumio1 volumio[3234]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 19 11:31:12 volumio1 volumio[3234]: info: Retrying Login Due to Network Error Aug 19 11:31:14 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:14 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:14 volumio1 volumio[3234]: info: Getting Spotify volume Aug 19 11:31:14 volumio1 volumio[3234]: (node:3234) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:31:14 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 19 11:31:14 volumio1 volumio[3234]: (node:3234) 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: 30) Aug 19 11:31:14 volumio1 volumio[3234]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Aug 19 11:31:14 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:14 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:14 volumio1 volumio[3234]: SPOTIFY: RECEIVED VOLUMIO VOLUME 48 Aug 19 11:31:15 volumio1 volumio[3234]: info: Initializing connection to go-librespot Websocket Aug 19 11:31:15 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 19 11:31:15 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 61. Aug 19 11:31:15 volumio1 volumio[3234]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 19 11:31:15 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 19 11:31:15 volumio1 systemd[1]: Started go-librespot Daemon. Aug 19 11:31:15 volumio1 go-librespot[5005]: Librespot-go daemon starting... Aug 19 11:31:15 volumio1 go-librespot[5005]: time="2024-08-19T11:31:15+08:00" level=info msg="generated new device id: 75c3062e9ff04970d12bd7608581a85f21f992aa" Aug 19 11:31:15 volumio1 go-librespot[5005]: time="2024-08-19T11:31:15+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 19 11:31:15 volumio1 go-librespot[5005]: time="2024-08-19T11:31:15+08:00" level=debug msg="obtained new client token: AABv62gioU5JqX3p1/N3bo9fedkcWnuKUzzzs+gHrOHe4k1VEcTksHUxItTEZ+0q7eI/7aes4UQVVMChfjXam28qVLbyDcLl0B9ptQ2gPjhkJQbhlJu4AgM24rOyU0k3vqLwr8ZJszl5Mmm2+CfarTxgT8dS7cifsFLY3Okqo1LNsyKkSP3JSsfSiompdPoyIBsZzjsLewB0uPCeh+xKPFP2ltrsU7Oean1mNlMTb8weg3FdRCk6efIRFLAfGA==" Aug 19 11:31:16 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:16 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:16 volumio1 go-librespot[5005]: time="2024-08-19T11:31:16+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 19 11:31:16 volumio1 go-librespot[5005]: time="2024-08-19T11:31:16+08:00" level=debug msg="completed keyexchange" Aug 19 11:31:16 volumio1 go-librespot[5005]: time="2024-08-19T11:31:16+08:00" level=debug msg="completed challenge" Aug 19 11:31:17 volumio1 go-librespot[5005]: time="2024-08-19T11:31:17+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 19 11:31:17 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 19 11:31:17 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 19 11:31:18 volumio1 volumio[3234]: info: CoreCommandRouter::volumioGetState Aug 19 11:31:18 volumio1 volumio[3234]: info: CorePlayQueue::getTrack 0 Aug 19 11:31:18 volumio1 volumio[3234]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 19 11:31:18 volumio1 volumio[3234]: Error: connect ETIMEDOUT 31.13.95.17:443 Aug 19 11:31:18 volumio1 volumio[3234]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Aug 19 11:31:18 volumio1 volumio[3234]: errno: -110, Aug 19 11:31:18 volumio1 volumio[3234]: code: 'ETIMEDOUT', Aug 19 11:31:18 volumio1 volumio[3234]: syscall: 'connect', Aug 19 11:31:18 volumio1 volumio[3234]: address: '31.13.95.17', Aug 19 11:31:18 volumio1 volumio[3234]: port: 443 Aug 19 11:31:18 volumio1 volumio[3234]: } Aug 19 11:31:18 volumio1 volumio[3234]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 19 11:31:19 volumio1 sudo[5028]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-19 11:30 Aug 19 11:31:19 volumio1 sudo[5028]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="6e682b9410d28f3874f90b2d7789db824a859264" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="7c81f20187867c3bd55475ead0f12800fe93082c" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 08 Jun 2024 10:32:20 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="orangepipc" VOLUMIO_DEVICENAME="Orange Pi PC" VOLUMIO_HASH="85fabbf1ff267d6584c35638894541bf"