-- Logs begin at Tue 2024-04-16 22:21:05 EDT, end at Wed 2024-04-17 00:46:11 EDT. -- Apr 17 00:45:00 volumiovm go-librespot[19224]: time="2024-04-17T00:45:00-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:00 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:00 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:00 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:00 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:00 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:03 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:03 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:03 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:03 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56752. Apr 17 00:45:03 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:03 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:03 volumiovm go-librespot[19247]: Librespot-go daemon starting... Apr 17 00:45:03 volumiovm go-librespot[19247]: time="2024-04-17T00:45:03-04:00" level=info msg="generated new device id: 64a84ad52300e084f0991e91982bcf3d3c2bad50" Apr 17 00:45:03 volumiovm go-librespot[19247]: time="2024-04-17T00:45:03-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:03 volumiovm go-librespot[19247]: time="2024-04-17T00:45:03-04:00" level=debug msg="obtained new client token: AACaP3bMqbQKEeSR7Ffqq80NXI6crbxOoK7Wrlk6t+O+qSP5UEOLNFaYqnOYjklfU+zzv+wrWeTb4z/arF5Fbr+fTsXr2NlEfKVtUB4AndzRBlJ+givjQBwMuAUzF/z4uq+sT8FAnlACMT5LEbxNPDkiJsDR6qSVYyIkyVezFhY6o54qBHB5Bh6TgDnf5sN3dO9kHOHhKl+dXeRBO66DpXpkuOofBQKam4nQIsN3JRpX5vUQ+fCZK+p9Ztx4" Apr 17 00:45:03 volumiovm go-librespot[19247]: time="2024-04-17T00:45:03-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:45:03 volumiovm go-librespot[19247]: time="2024-04-17T00:45:03-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:03 volumiovm go-librespot[19247]: time="2024-04-17T00:45:03-04:00" level=debug msg="completed challenge" Apr 17 00:45:04 volumiovm go-librespot[19247]: time="2024-04-17T00:45:04-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:04 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:04 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:06 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:06 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:07 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:07 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56753. Apr 17 00:45:07 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:07 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:07 volumiovm go-librespot[19258]: Librespot-go daemon starting... Apr 17 00:45:07 volumiovm go-librespot[19258]: time="2024-04-17T00:45:07-04:00" level=info msg="generated new device id: 64575a5cfaad5ef98687e8238ddb2294cebdf7bd" Apr 17 00:45:07 volumiovm go-librespot[19258]: time="2024-04-17T00:45:07-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:07 volumiovm go-librespot[19258]: time="2024-04-17T00:45:07-04:00" level=debug msg="obtained new client token: AADR/inBJ7mdzqErTHbcdnHgv8SwGO0OREwZWFZkIXMAzbr5tMQ/dbwA0AsGB+ApYl7TSrdJ5ytX4tij92VvGVfJSCc+J44D7PsPqJG3CXILNYFhJ9oZjJAmVSYmqMBVI0NlipKSAeZiN7TPOaQ8pUxTy1IJ24Vl8e+paOQ9eJbgf8qiABAAWz1WzKVi3g8sEtTu9fxuJYqpmq7b/lZGGK8Xf3txA7KGyhH+2Lphj75B+5LyS0E9+JTvobUW" Apr 17 00:45:07 volumiovm go-librespot[19258]: time="2024-04-17T00:45:07-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:45:07 volumiovm go-librespot[19258]: time="2024-04-17T00:45:07-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:07 volumiovm go-librespot[19258]: time="2024-04-17T00:45:07-04:00" level=debug msg="completed challenge" Apr 17 00:45:08 volumiovm go-librespot[19258]: time="2024-04-17T00:45:08-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:08 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:08 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:08 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:09 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:09 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:10 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:10 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:10 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:11 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:11 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56754. Apr 17 00:45:11 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:11 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:11 volumiovm go-librespot[19291]: Librespot-go daemon starting... Apr 17 00:45:11 volumiovm go-librespot[19291]: time="2024-04-17T00:45:11-04:00" level=info msg="generated new device id: b89fad8dbca6d24732f8a2143fdc62a5ed6a9ebd" Apr 17 00:45:11 volumiovm go-librespot[19291]: time="2024-04-17T00:45:11-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:11 volumiovm go-librespot[19291]: time="2024-04-17T00:45:11-04:00" level=debug msg="obtained new client token: AAD8RWBtuIkreA/hGlDXp0KpgECGJezyRbOvg6feBClQhldFbnWgtdOJUAdocI9n3lVZjmAuR1WQQX1qWHlOrOu9/1qjNQ52YAzfXsFIqut8aP4ioaqaBQhm6rAp8xJ9IumIRUZoZoNWPgqzugByIn7tzSjHwCCTZfWCVIp7ILzu97FTnuzCNS55TdxFjGZY21Qm66SWPxxpsAQFaQ3AhxLFwPES55ZSfjBqPP06RocFMTzqndz071cJ0qbA" Apr 17 00:45:11 volumiovm go-librespot[19291]: time="2024-04-17T00:45:11-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:11 volumiovm go-librespot[19291]: time="2024-04-17T00:45:11-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:11 volumiovm go-librespot[19291]: time="2024-04-17T00:45:11-04:00" level=debug msg="completed challenge" Apr 17 00:45:12 volumiovm go-librespot[19291]: time="2024-04-17T00:45:12-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:12 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:12 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:12 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:12 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:15 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:15 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56755. Apr 17 00:45:15 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:15 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:15 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:15 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:15 volumiovm go-librespot[19301]: Librespot-go daemon starting... Apr 17 00:45:15 volumiovm go-librespot[19301]: time="2024-04-17T00:45:15-04:00" level=info msg="generated new device id: 12156d7c5c692242df5a723fe5299f281eeef969" Apr 17 00:45:15 volumiovm go-librespot[19301]: time="2024-04-17T00:45:15-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:15 volumiovm go-librespot[19301]: time="2024-04-17T00:45:15-04:00" level=debug msg="obtained new client token: AADd2HQpc86gfj9vloRR4CLU+gU4UEBBSswLliIfGD05MpktsoFq414AamQFYjW/93EtU+r72biTavyLXZAv1O7tiVGYA/uKeC8LLLKG0Cn3iqycOEwjGQ7lYjhdIo8fKR4jLHf85+iTS22GZ+77dlrUCcHLWMvBfqrGgD7RK0XDowFZCmLhP3IH+2Hw+jhcbmOZWWnLDq3/qXoZ/CK/zOXxUD2hpM5oRS6+s3O0Hx5DcSj1WkEmx6jZYs00" Apr 17 00:45:15 volumiovm go-librespot[19301]: time="2024-04-17T00:45:15-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:45:15 volumiovm go-librespot[19301]: time="2024-04-17T00:45:15-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:15 volumiovm go-librespot[19301]: time="2024-04-17T00:45:15-04:00" level=debug msg="completed challenge" Apr 17 00:45:16 volumiovm go-librespot[19301]: time="2024-04-17T00:45:16-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:16 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:16 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:18 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:18 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:18 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:18 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:18 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:19 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:19 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56756. Apr 17 00:45:19 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:19 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:19 volumiovm go-librespot[19324]: Librespot-go daemon starting... Apr 17 00:45:19 volumiovm go-librespot[19324]: time="2024-04-17T00:45:19-04:00" level=info msg="generated new device id: 2b0563c6415bd361c6ff4af64ed2b815e6b46ab4" Apr 17 00:45:19 volumiovm go-librespot[19324]: time="2024-04-17T00:45:19-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:19 volumiovm go-librespot[19324]: time="2024-04-17T00:45:19-04:00" level=debug msg="obtained new client token: AAAqbNesfUOM6Q4xkWTekBfnpfh84mr39yvR6hGsEKhdHninORR75lX0rKa8Q3oiQMxVln7Cow+qJGbpbE5UZJ2r1IKsGigF0skE+OtMHiEEh0aqspgH2y2eHentk96dnwF6ghZtStfXft3nSLQtbN3bmCVhGyEKgXChiaHOQnzr817l2226ByqOQqev7dOk2W2YMpzFUK9wcnKvMjefzdwCyLrVxV/jugFb3Q7KRU/zGFB2XLX1VQSYiaQh" Apr 17 00:45:19 volumiovm go-librespot[19324]: time="2024-04-17T00:45:19-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:45:19 volumiovm go-librespot[19324]: time="2024-04-17T00:45:19-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:19 volumiovm go-librespot[19324]: time="2024-04-17T00:45:19-04:00" level=debug msg="completed challenge" Apr 17 00:45:20 volumiovm go-librespot[19324]: time="2024-04-17T00:45:20-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:20 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:20 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:20 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:21 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:21 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:23 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:23 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56757. Apr 17 00:45:23 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:23 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:23 volumiovm go-librespot[19393]: Librespot-go daemon starting... Apr 17 00:45:23 volumiovm go-librespot[19393]: time="2024-04-17T00:45:23-04:00" level=info msg="generated new device id: 0aa5bf2218e837ae264566a34f44a7260e7d8af4" Apr 17 00:45:23 volumiovm go-librespot[19393]: time="2024-04-17T00:45:23-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:23 volumiovm go-librespot[19393]: time="2024-04-17T00:45:23-04:00" level=debug msg="obtained new client token: AADuAzisr2vYJjLy/qdo6elnHpdmPo6Ud3fWV+8slDhh5bRw5rqDowKZ60jntssxoZlWqZ54zN2F7ZYATOLmOFeLncqGc1k33ZevYKVCunQGuEBRRthAIes2p618Sg1AYZ1gmcy5/CiRIv7ydyeFT0hdFAHBYE7Gr1K5TpJOr2rc6mnqPZIiu1zyzykp6OhRKqOI7cbDeYpFpXOPMb7vFwel5UPBBlPXOiSdeFOX3EXiMyGKS4UeGILYyjrK" Apr 17 00:45:23 volumiovm go-librespot[19393]: time="2024-04-17T00:45:23-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:23 volumiovm go-librespot[19393]: time="2024-04-17T00:45:23-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:23 volumiovm go-librespot[19393]: time="2024-04-17T00:45:23-04:00" level=debug msg="completed challenge" Apr 17 00:45:24 volumiovm go-librespot[19393]: time="2024-04-17T00:45:24-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:24 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:24 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:24 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:24 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:27 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:27 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56758. Apr 17 00:45:27 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:27 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:27 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:27 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:27 volumiovm go-librespot[19405]: Librespot-go daemon starting... Apr 17 00:45:27 volumiovm go-librespot[19405]: time="2024-04-17T00:45:27-04:00" level=info msg="generated new device id: 7e5412fad6b6fa218e04733f4d0f20d9f1a34a68" Apr 17 00:45:27 volumiovm go-librespot[19405]: time="2024-04-17T00:45:27-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:27 volumiovm go-librespot[19405]: time="2024-04-17T00:45:27-04:00" level=debug msg="obtained new client token: AADCjhLYSpsp2Kg0GQ4EjvuBgKbcMF8MG3l4u/pd9gm7qIeRUQPsbfP58G78sTH9T+aRVvbLF/hesQaZy5hpEULJfKINxfpP6nIQdEwLqPCM7HSD9anh9Yh5IT8m4VEzqu0kdMCQSBbxjgVG1VYvIo4HS9U9N+STaNer9xDdcnF/My8FPcuODZVWxLGtruJoMO7CDh2xOv2cXZGrWSupw6nk77JDWSEQ21OwvoSds7bJrbe0f40VrUKIW/5O" Apr 17 00:45:27 volumiovm go-librespot[19405]: time="2024-04-17T00:45:27-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:27 volumiovm go-librespot[19405]: time="2024-04-17T00:45:27-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:27 volumiovm go-librespot[19405]: time="2024-04-17T00:45:27-04:00" level=debug msg="completed challenge" Apr 17 00:45:28 volumiovm go-librespot[19405]: time="2024-04-17T00:45:28-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:28 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:28 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:28 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:28 volumiovm volumio[768]: info: Tunnel connection is inactive, restarting it Apr 17 00:45:28 volumiovm volumio[768]: info: Starting Tunnel 1 Apr 17 00:45:28 volumiovm volumio[768]: info: Starting Tunnel Connection Checker Apr 17 00:45:29 volumiovm sudo[19431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Apr 17 00:45:29 volumiovm sudo[19431]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 00:45:29 volumiovm autossh[18415]: received signal to exit (15) Apr 17 00:45:29 volumiovm systemd[1]: Stopping MyVolumio SSH Tunnel... Apr 17 00:45:29 volumiovm systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM Apr 17 00:45:29 volumiovm systemd[1]: sshtunnel.service: Succeeded. Apr 17 00:45:29 volumiovm volumio[768]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 17 00:45:29 volumiovm systemd[1]: Stopped MyVolumio SSH Tunnel. Apr 17 00:45:29 volumiovm volumio[768]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Apr 17 00:45:29 volumiovm systemd[1]: Started MyVolumio SSH Tunnel. Apr 17 00:45:29 volumiovm sudo[19431]: pam_unix(sudo:session): session closed for user root Apr 17 00:45:29 volumiovm volumio[768]: info: Remote SSH Started Apr 17 00:45:29 volumiovm autossh[19434]: port set to 0, monitoring disabled Apr 17 00:45:29 volumiovm autossh[19434]: starting ssh (count 1) Apr 17 00:45:29 volumiovm autossh[19434]: ssh child pid is 19437 Apr 17 00:45:29 volumiovm volumio[768]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 17 00:45:29 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:29 volumiovm volumiossh-tunnel[19433]: Warning: Permanently added '[us1.myvolumio.org]:2222,[162.243.167.188]:2222' (RSA) to the list of known hosts. Apr 17 00:45:30 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:30 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:30 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:30 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:30 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:31 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:31 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56759. Apr 17 00:45:31 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:31 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:31 volumiovm go-librespot[19449]: Librespot-go daemon starting... Apr 17 00:45:31 volumiovm go-librespot[19449]: time="2024-04-17T00:45:31-04:00" level=info msg="generated new device id: cb02dc8606edc1c82bf9ab4b4efc921ec68e513e" Apr 17 00:45:31 volumiovm go-librespot[19449]: time="2024-04-17T00:45:31-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:31 volumiovm go-librespot[19449]: time="2024-04-17T00:45:31-04:00" level=debug msg="obtained new client token: AABPqrYAClpIn0k9ydy+Hv1jwk1DCwmwPAmU8fq1QxbZ1VgLy4B4P/2fMdxs1l8vnC3swUzEB3Li9SzmiiiT0Y11TAfasix2WPz/uFf5Ii1wKngNi+huM1wpxmvaLEi/ak0OIGUMjXndg65FMCNjFWGIEw4SrPKg+VaKduQLV5oinO/peMU8QhnGgiVIToX8OMV35LJn6JKWN01ZEOmDBX4Zp5VxTOElgnl/PeLndg4NbeasxkpD93vjsYVN" Apr 17 00:45:31 volumiovm go-librespot[19449]: time="2024-04-17T00:45:31-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:31 volumiovm go-librespot[19449]: time="2024-04-17T00:45:31-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:32 volumiovm go-librespot[19449]: time="2024-04-17T00:45:32-04:00" level=debug msg="completed challenge" Apr 17 00:45:32 volumiovm go-librespot[19449]: time="2024-04-17T00:45:32-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:32 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:32 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:33 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:33 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:35 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:35 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56760. Apr 17 00:45:35 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:35 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:35 volumiovm go-librespot[19460]: Librespot-go daemon starting... Apr 17 00:45:35 volumiovm go-librespot[19460]: time="2024-04-17T00:45:35-04:00" level=info msg="generated new device id: 67cc19a31c2f9cbcddf5d69853393015c5ad1508" Apr 17 00:45:35 volumiovm go-librespot[19460]: time="2024-04-17T00:45:35-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:35 volumiovm go-librespot[19460]: time="2024-04-17T00:45:35-04:00" level=debug msg="obtained new client token: AACFxsYI6Oq+0mX4GJd0BuQpqv6B8ybzO1pXUAWMrBbztnevtAc4G5yTm7HeFsZkCUNXTLj/To5UlhHpYIaJdahgSrBAst8tWas3ZvozDNNhx69Zd5gQbeqYOiIfeOXlzR7QpTwz5yaw6nvMboSUcBHU7V6DnUH7rQGjBPujQzrU87ncyvxRjTjsm7F3jbZXuyP50UjiwQir/DEwxX5dLq3y8mbOdbu15IwnGlLYI1R27ey8gyQ+FWehht6D" Apr 17 00:45:35 volumiovm go-librespot[19460]: time="2024-04-17T00:45:35-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:45:35 volumiovm go-librespot[19460]: time="2024-04-17T00:45:35-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:35 volumiovm go-librespot[19460]: time="2024-04-17T00:45:35-04:00" level=debug msg="completed challenge" Apr 17 00:45:36 volumiovm go-librespot[19460]: time="2024-04-17T00:45:36-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:36 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:36 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:36 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:36 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:38 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:38 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:38 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:39 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:39 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56761. Apr 17 00:45:39 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:39 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:39 volumiovm go-librespot[19482]: Librespot-go daemon starting... Apr 17 00:45:39 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:39 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:39 volumiovm go-librespot[19482]: time="2024-04-17T00:45:39-04:00" level=info msg="generated new device id: 76f0a86c3c301d6a69d382d34223c4ff62daced5" Apr 17 00:45:39 volumiovm go-librespot[19482]: time="2024-04-17T00:45:39-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:39 volumiovm go-librespot[19482]: time="2024-04-17T00:45:39-04:00" level=debug msg="obtained new client token: AACqOTx9vf4GoCydF/e0naYATtYviCCwPCN3aAyO+ZsKoWahJZXhhauQofVAhVMlNokpWViOxFhiFeZeZ2wQSAwmbUvLCk/yNu6ZqCaF8bidfKr8Vrk+3z1OmfbSyEL6J6+l1yPvjyfhd6Eao5xCOORNPY7UB1tqNv0ARWPW7beMf1mNQrnMDnTehmFC8qMkzv5hLUaDAX/UtYyOH4o8s6lnVcFbeDVdGS+lnN4Rc3xvi2/ByK1Xx4TwPH66" Apr 17 00:45:39 volumiovm go-librespot[19482]: time="2024-04-17T00:45:39-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:39 volumiovm go-librespot[19482]: time="2024-04-17T00:45:39-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:39 volumiovm go-librespot[19482]: time="2024-04-17T00:45:39-04:00" level=debug msg="completed challenge" Apr 17 00:45:39 volumiovm go-librespot[19482]: time="2024-04-17T00:45:39-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:40 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:40 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:40 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:42 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:42 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:43 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:43 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56762. Apr 17 00:45:43 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:43 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:43 volumiovm go-librespot[19504]: Librespot-go daemon starting... Apr 17 00:45:43 volumiovm go-librespot[19504]: time="2024-04-17T00:45:43-04:00" level=info msg="generated new device id: fa63171dcdb01170654801484024e07686810de4" Apr 17 00:45:43 volumiovm go-librespot[19504]: time="2024-04-17T00:45:43-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:43 volumiovm go-librespot[19504]: time="2024-04-17T00:45:43-04:00" level=debug msg="obtained new client token: AABc6KevV66lYMTtivPLdRSFgA5toAKFQ3faGN1S45pQAh4ohPXsRL3GPi48YebhUM9+j1jqkBUDnsOtIbIaExFxOAAsCUF0Y8Ks7B2IyuD5TL65D7n4ZGnyvdh7i48EJVm3hcyHTnZRT9lR+4507raSItS4UjO8y2d0m/j5fMzfMbYFN8NvIMqAS61OQu6DciEt5jLsvPWuvFQHfz2dp8LEEXLkGMkOLsJ3imSwLojvyEUYihGnxbuA9gc7" Apr 17 00:45:43 volumiovm go-librespot[19504]: time="2024-04-17T00:45:43-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:43 volumiovm go-librespot[19504]: time="2024-04-17T00:45:43-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:43 volumiovm go-librespot[19504]: time="2024-04-17T00:45:43-04:00" level=debug msg="completed challenge" Apr 17 00:45:44 volumiovm go-librespot[19504]: time="2024-04-17T00:45:44-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:44 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:44 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:45 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:45 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:47 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:47 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56763. Apr 17 00:45:47 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:47 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:47 volumiovm go-librespot[19514]: Librespot-go daemon starting... Apr 17 00:45:47 volumiovm go-librespot[19514]: time="2024-04-17T00:45:47-04:00" level=info msg="generated new device id: 1bdb303a5f50d7a31c3ca9f2da63662dfa55f843" Apr 17 00:45:47 volumiovm go-librespot[19514]: time="2024-04-17T00:45:47-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:47 volumiovm go-librespot[19514]: time="2024-04-17T00:45:47-04:00" level=debug msg="obtained new client token: AAAQxZKEzx3g6jeLMZYitTmqv6zKRZME0JYSzEnSVFOgiK2hFODntBooRs5eiUu1ZpQleJezHcDZulkX6RlGKpPlt9mDzXy+l2mDUVSYVQcjXKB3j0kvxPlY8ppguybTGorj8FL/ORztIgHIosfx4XtTpUhI+D1XChz6E+VAfiJHVz32FFG7VLj0MiKOwcYcHY6YsIudozCSC/unTpMp+cm1SIzzTwKJPtDd5GXQ0YaWWj68XxPlgyFF+a9K" Apr 17 00:45:47 volumiovm go-librespot[19514]: time="2024-04-17T00:45:47-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:47 volumiovm go-librespot[19514]: time="2024-04-17T00:45:47-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:47 volumiovm go-librespot[19514]: time="2024-04-17T00:45:47-04:00" level=debug msg="completed challenge" Apr 17 00:45:47 volumiovm go-librespot[19514]: time="2024-04-17T00:45:47-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:47 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:47 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:48 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:48 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:48 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:50 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:50 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:50 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:51 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:51 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56764. Apr 17 00:45:51 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:51 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:51 volumiovm go-librespot[19548]: Librespot-go daemon starting... Apr 17 00:45:51 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:51 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:51 volumiovm go-librespot[19548]: time="2024-04-17T00:45:51-04:00" level=info msg="generated new device id: 6c68f8a818c21f59b842b6fb6d7d2cf59e90db11" Apr 17 00:45:51 volumiovm go-librespot[19548]: time="2024-04-17T00:45:51-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:51 volumiovm go-librespot[19548]: time="2024-04-17T00:45:51-04:00" level=debug msg="obtained new client token: AACllBF9/PBSduOv18we2OlZLbbXjSLijU4mGmJdvO0+aTyzgQozt2PoIrZa0OxIeYOOmW22BZ25lv/xJ/I9ee2VnTEaIu1Aw6sKknfIri6iwkC6baJD0Of2PJsVCKycsXWRLxNzqhlPA6TwhfqO/2uDjUthOawFwM+Y7foBha/adHr8N3y4tE2S46TdQws3TO5jLCM4fG2Befyv5Mb3ob36TlG4Ji20RFW0YaXKfeWtkjVHCBLQsx14eP6Y" Apr 17 00:45:51 volumiovm go-librespot[19548]: time="2024-04-17T00:45:51-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:51 volumiovm go-librespot[19548]: time="2024-04-17T00:45:51-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:51 volumiovm go-librespot[19548]: time="2024-04-17T00:45:51-04:00" level=debug msg="completed challenge" Apr 17 00:45:52 volumiovm go-librespot[19548]: time="2024-04-17T00:45:52-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:52 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:52 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:54 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:54 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:55 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:55 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56765. Apr 17 00:45:55 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:55 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:55 volumiovm go-librespot[19560]: Librespot-go daemon starting... Apr 17 00:45:55 volumiovm go-librespot[19560]: time="2024-04-17T00:45:55-04:00" level=info msg="generated new device id: fd827a99c555b132554e255f5f115d62574b3652" Apr 17 00:45:55 volumiovm go-librespot[19560]: time="2024-04-17T00:45:55-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:55 volumiovm go-librespot[19560]: time="2024-04-17T00:45:55-04:00" level=debug msg="obtained new client token: AACZKkk7i9DWmCceJ1V2UhPel6h0A5vlLh39k/cp+r05n0Mz+U22IKneAB7naIorjtGbh0h0Y40FQw6i0M14CGaOkc/lsr+1Z9KZLPbJ+8+2wI8OGShaDKufZygADNbijh34Cs+SNu7ZqJmYoR+B4ezFJPGSM3TZRusNoIBHdssMD4qoHwkFzywsnmH7rqYPbmzjfOqJyvD9NndmqsAFnZX03d5KMP8elBJJ4ZJDuwQcldhXqpTxlme2BZ3E" Apr 17 00:45:55 volumiovm go-librespot[19560]: time="2024-04-17T00:45:55-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-gae2.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 17 00:45:55 volumiovm go-librespot[19560]: time="2024-04-17T00:45:55-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:55 volumiovm go-librespot[19560]: time="2024-04-17T00:45:55-04:00" level=debug msg="completed challenge" Apr 17 00:45:56 volumiovm go-librespot[19560]: time="2024-04-17T00:45:56-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:45:56 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:45:56 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:45:57 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:45:57 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:45:58 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:45:58 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:58 volumiovm volumio[768]: info: Listing playlists Apr 17 00:45:59 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:45:59 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56766. Apr 17 00:45:59 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:45:59 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:45:59 volumiovm go-librespot[19582]: Librespot-go daemon starting... Apr 17 00:45:59 volumiovm go-librespot[19582]: time="2024-04-17T00:45:59-04:00" level=info msg="generated new device id: df061396d420c62b3cdad65093f66ffbba34ad6e" Apr 17 00:45:59 volumiovm go-librespot[19582]: time="2024-04-17T00:45:59-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:45:59 volumiovm go-librespot[19582]: time="2024-04-17T00:45:59-04:00" level=debug msg="obtained new client token: AAAMiy+HOFD5Ze5oQ34WIEhNkVh90i1m/NBJNvW8xULNdEqyezyMEx0j9pS8NeyxaAPXWEfpsfpCv1vqN2y39i6/q97lW1DhZ+lx8Do1D62s83aZA36KLMDGAatr6lE5OS4kGwv3h3Bkwq0TBqGUZN8Rk9Uet6HSlUOOOfc8fLsyZ85sBpW3XToKOGiEh+KcuKqS3+WyaAA2riIqyCBGVKMlxlf2Ak5cWEGf8KTUOJS6YQIZTkiyzL43flQ8" Apr 17 00:45:59 volumiovm go-librespot[19582]: time="2024-04-17T00:45:59-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:45:59 volumiovm go-librespot[19582]: time="2024-04-17T00:45:59-04:00" level=debug msg="completed keyexchange" Apr 17 00:45:59 volumiovm go-librespot[19582]: time="2024-04-17T00:45:59-04:00" level=debug msg="completed challenge" Apr 17 00:46:00 volumiovm go-librespot[19582]: time="2024-04-17T00:46:00-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:46:00 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:46:00 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:46:00 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:46:00 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:46:00 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:46:03 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:46:03 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56767. Apr 17 00:46:03 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:46:03 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:46:03 volumiovm go-librespot[19603]: Librespot-go daemon starting... Apr 17 00:46:03 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:46:03 volumiovm go-librespot[19603]: time="2024-04-17T00:46:03-04:00" level=info msg="generated new device id: b686903a27fb8a52f6c8350300dd93e87ff79c69" Apr 17 00:46:03 volumiovm go-librespot[19603]: time="2024-04-17T00:46:03-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:46:03 volumiovm go-librespot[19603]: time="2024-04-17T00:46:03-04:00" level=debug msg="new websocket client" Apr 17 00:46:03 volumiovm volumio[768]: info: Connection to go-librespot Websocket established Apr 17 00:46:03 volumiovm go-librespot[19603]: time="2024-04-17T00:46:03-04:00" level=debug msg="obtained new client token: AAAzsWj1pMYJ/mWGZ8EMPL9NT6V0X+f6g5Jxl9SeKWFrsxucWBVfHYwFhiBJDuyzB2pw/A18/PNg6+2R/ok1POMOOE5IPFk3ShIpvXMue0q6+BDu3c+hcVMlggrq6X0nZxa8AmestFsngsYEoeC20ZTRqYz51yeZ5IueenEhKBXMlPP1ZrvCcgmF3u/BZhE9jizj1CP6JZaTso24Wh+BtnuWFHIP4uy5Y4fpiRPbegIfICBaC6GAzL1Rigur" Apr 17 00:46:03 volumiovm go-librespot[19603]: time="2024-04-17T00:46:03-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:46:03 volumiovm go-librespot[19603]: time="2024-04-17T00:46:03-04:00" level=debug msg="completed keyexchange" Apr 17 00:46:03 volumiovm go-librespot[19603]: time="2024-04-17T00:46:03-04:00" level=debug msg="completed challenge" Apr 17 00:46:04 volumiovm go-librespot[19603]: time="2024-04-17T00:46:04-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:46:04 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:46:04 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:46:04 volumiovm volumio[768]: info: Connection to go-librespot Websocket closed Apr 17 00:46:06 volumiovm volumio[768]: info: Getting Spotify volume Apr 17 00:46:06 volumiovm volumio[768]: (node:768) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:46:06 volumiovm volumio[768]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Apr 17 00:46:06 volumiovm volumio[768]: (node:768) 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: 7137) Apr 17 00:46:06 volumiovm volumio[768]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 17 00:46:06 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:46:06 volumiovm volumio[768]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 17 00:46:06 volumiovm volumio[768]: SPOTIFY: SPOTIFY VOLUME 100 Apr 17 00:46:06 volumiovm volumio[768]: SPOTIFY: VOLUMIO VOLUME 100 Apr 17 00:46:06 volumiovm volumio[768]: SPOTIFY: DELTA VOLUME ENOUGH: false Apr 17 00:46:07 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:46:07 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:46:07 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:46:07 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56768. Apr 17 00:46:07 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:46:07 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:46:07 volumiovm go-librespot[19614]: Librespot-go daemon starting... Apr 17 00:46:07 volumiovm go-librespot[19614]: time="2024-04-17T00:46:07-04:00" level=info msg="generated new device id: 738c32245493850cee6f8f59b6688087105cf9bc" Apr 17 00:46:07 volumiovm go-librespot[19614]: time="2024-04-17T00:46:07-04:00" level=debug msg="stored credentials found for jwf8666" Apr 17 00:46:07 volumiovm go-librespot[19614]: time="2024-04-17T00:46:07-04:00" level=debug msg="obtained new client token: AAAA2VBI1QF894nExrSE7wMUfYeRyiPS8U4M5qbsNK7xJ/mnzDx6igqu8JjXadHbja5mKYLNN+IPG4PoXWz/ZFopDk4lBR8PO1g5e6PzezFeAOjz3fYEsOg6FSsCVyVWHgUQQfNQivmHaXnYsD6amfkdC9yhADkGoMItkraXiqY7nhCnwWkwAI/FudHFIWjJ1bcEX7z1aoAfqubJv8KUXoPcoNRRHIDZymP0kp6Flolses/4RZcw/E4kZfMo" Apr 17 00:46:07 volumiovm go-librespot[19614]: time="2024-04-17T00:46:07-04:00" level=debug msg="fetched new accesspoints: [ap-gue1.spotify.com:4070 ap-gue1.spotify.com:443 ap-gue1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gae2.spotify.com:443 ap-gew1.spotify.com:80]" Apr 17 00:46:07 volumiovm go-librespot[19614]: time="2024-04-17T00:46:07-04:00" level=debug msg="completed keyexchange" Apr 17 00:46:07 volumiovm volumio[768]: info: Apr 17 00:46:07 volumiovm volumio[768]: ---------------------------- MPD announces system playlist update Apr 17 00:46:07 volumiovm volumio[768]: info: Ignoring MPD Status Update Apr 17 00:46:07 volumiovm volumio[768]: info: Apr 17 00:46:07 volumiovm volumio[768]: ---------------------------- MPD announces state update: player Apr 17 00:46:07 volumiovm volumio[768]: info: ControllerMpd::getState Apr 17 00:46:07 volumiovm volumio[768]: verbose: ControllerMpd::sendMpdCommand status Apr 17 00:46:07 volumiovm volumio[768]: info: ------------------------------ 1ms Apr 17 00:46:07 volumiovm volumio[768]: info: sendMpdCommand status took 0 milliseconds Apr 17 00:46:07 volumiovm volumio[768]: verbose: ControllerMpd::parseState Apr 17 00:46:07 volumiovm volumio[768]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 17 00:46:07 volumiovm volumio[768]: info: sendMpdCommand playlistinfo took 0 milliseconds Apr 17 00:46:07 volumiovm volumio[768]: verbose: ControllerMpd::parseTrackInfo Apr 17 00:46:07 volumiovm volumio[768]: info: ControllerMpd::pushState Apr 17 00:46:07 volumiovm volumio[768]: info: CoreCommandRouter::servicePushState Apr 17 00:46:07 volumiovm volumio[768]: info: CorePlayQueue::getTrack 0 Apr 17 00:46:07 volumiovm volumio[768]: verbose: STATE SERVICE {"status":"play","position":0,"seek":220719331,"duration":0,"samplerate":44.1,"bitdepth":"32 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"63 Kbps","isStreaming":false,"title":"Airmate - At The Waterfront","artist":"DMD2 Music - A Touch Of Class","album":null,"uri":"http://ch-be04-ice.dmd2streaming.com/ad_atouchofclass.aacp","trackType":"aacp"} Apr 17 00:46:07 volumiovm volumio[768]: verbose: CURRENT POSITION 0 Apr 17 00:46:07 volumiovm volumio[768]: info: CoreStateMachine::syncState stateService play Apr 17 00:46:07 volumiovm volumio[768]: info: CoreStateMachine::syncState currentStatus play Apr 17 00:46:07 volumiovm volumio[768]: info: Received an update from plugin. extracting info from payload Apr 17 00:46:07 volumiovm volumio[768]: info: CoreStateMachine::pushState Apr 17 00:46:07 volumiovm volumio[768]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 17 00:46:07 volumiovm volumio[768]: info: CoreCommandRouter::volumioPushState Apr 17 00:46:07 volumiovm volumio[768]: info: MRS: Pushing multiroomSync output update for this device Apr 17 00:46:07 volumiovm volumio[768]: info: MRS: Pushing multiroomSync output Apr 17 00:46:07 volumiovm volumio[768]: info: CoreStateMachine::pushState Apr 17 00:46:07 volumiovm volumio[768]: info: CoreCommandRouter::volumioPushState Apr 17 00:46:07 volumiovm volumio[768]: info: MRS: Pushing multiroomSync output update for this device Apr 17 00:46:07 volumiovm volumio[768]: info: MRS: Pushing multiroomSync output Apr 17 00:46:07 volumiovm volumio[768]: info: ------------------------------ 9ms Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] using existing timer Apr 17 00:46:07 volumiovm volumio[768]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Airmate - At The Waterfront | previous title: Alien Army - Scratchoetry Apr 17 00:46:07 volumiovm volumio[768]: info: =================> [timer] is active: false | can continue: false | timer started at: 1713328944052 Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] Split composite title into artist: Airmate and title: At The Waterfront Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] Updating now playing Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] starting new timer for 120000 milliseconds [DMD2 Music - A Touch Of Class - Airmate - At The Waterfront]. Apr 17 00:46:07 volumiovm volumio[768]: -------------------------------------------------// S T A R T I N G Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] Timer started with time stamp 1713329167 Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: SPOTIFY VOLUME 100 Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: VOLUMIO VOLUME 100 Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: DELTA VOLUME ENOUGH: false Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] using existing timer Apr 17 00:46:07 volumiovm volumio[768]: info: --------------------------------------------------------------------// [LastFM] new state has been pushed; status: play | service: webradio | duration: 0 | title: Airmate - At The Waterfront | previous title: Airmate - At The Waterfront Apr 17 00:46:07 volumiovm volumio[768]: info: =================> [timer] is active: true | can continue: false | timer started at: 1713329167827 Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] Playback detected, evaluating parameters for scrobbling... Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] Same state as the one previously pushed. No need to do anything... Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: SPOTIFY VOLUME 100 Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: VOLUMIO VOLUME 100 Apr 17 00:46:07 volumiovm volumio[768]: SPOTIFY: DELTA VOLUME ENOUGH: false Apr 17 00:46:07 volumiovm go-librespot[19614]: time="2024-04-17T00:46:07-04:00" level=debug msg="completed challenge" Apr 17 00:46:07 volumiovm volumio[768]: info: [LastFM] updated "now playing" | artist: Airmate | title: At The Waterfront Apr 17 00:46:08 volumiovm go-librespot[19614]: time="2024-04-17T00:46:08-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Apr 17 00:46:08 volumiovm systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 17 00:46:08 volumiovm systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 17 00:46:08 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:46:10 volumiovm volumio[768]: info: Initializing connection to go-librespot Websocket Apr 17 00:46:10 volumiovm volumio[768]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 17 00:46:10 volumiovm volumio[768]: info: CoreCommandRouter::volumioGetState Apr 17 00:46:10 volumiovm volumio[768]: info: Listing playlists Apr 17 00:46:10 volumiovm volumio[768]: info: Listing playlists Apr 17 00:46:10 volumiovm volumio[768]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 17 00:46:10 volumiovm volumio[768]: TypeError: Cannot read property '@' of null Apr 17 00:46:10 volumiovm volumio[768]: at Object.callback (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:342:14) Apr 17 00:46:10 volumiovm volumio[768]: at /data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:60:13 Apr 17 00:46:10 volumiovm volumio[768]: at Parser. (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:304:18) Apr 17 00:46:10 volumiovm volumio[768]: at Parser.emit (events.js:400:28) Apr 17 00:46:10 volumiovm volumio[768]: at Parser.exports.Parser.Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:314:16) Apr 17 00:46:10 volumiovm volumio[768]: at Parser.parseString (/data/plugins/user_interface/lastfm/node_modules/xml2js/lib/parser.js:5:59) Apr 17 00:46:10 volumiovm volumio[768]: at IncomingMessage. (/data/plugins/user_interface/lastfm/node_modules/simple-lastfm/lib/index.js:58:14) Apr 17 00:46:10 volumiovm volumio[768]: at IncomingMessage.emit (events.js:412:35) Apr 17 00:46:10 volumiovm volumio[768]: at endReadableNT (internal/streams/readable.js:1333:12) Apr 17 00:46:10 volumiovm volumio[768]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Apr 17 00:46:10 volumiovm volumio[768]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 17 00:46:11 volumiovm systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 17 00:46:11 volumiovm systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56769. Apr 17 00:46:11 volumiovm systemd[1]: Stopped go-librespot Daemon. Apr 17 00:46:11 volumiovm systemd[1]: Started go-librespot Daemon. Apr 17 00:46:11 volumiovm go-librespot[19656]: Librespot-go daemon starting... Apr 17 00:46:11 volumiovm sudo[19658]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-17 00:45 Apr 17 00:46:11 volumiovm sudo[19658]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 17 00:46:11 volumiovm go-librespot[19656]: time="2024-04-17T00:46:11-04:00" level=info msg="generated new device id: b693590bacd4ecfcdedad2cb8f2c7ac1911665a0" Apr 17 00:46:11 volumiovm go-librespot[19656]: time="2024-04-17T00:46:11-04:00" level=debug msg="stored credentials found for jwf8666" 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="7b9cb4a8b52fb7148a38d6ac651c1c29e09bb92c" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="b1dcc17f6d31bf91f0abd3c3fa57506d1e0d2b6b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 01 Mar 2024 08:52:33 PM CET" VOLUMIO_VERSION="3.634" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="93edfc70711724967af109c0a39fa069"