-- Logs begin at Tue 2025-03-04 19:17:08 CST, end at Tue 2025-03-04 20:04:30 CST. -- Mar 04 20:03:01 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:01 dac.x2-nvme volumio[1363]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:01 dac.x2-nvme volumio[1363]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Mar 04 20:03:01 dac.x2-nvme volumio[1363]: info: Retrying Login Due to Network Error Mar 04 20:03:02 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 04 20:03:02 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 262. Mar 04 20:03:02 dac.x2-nvme systemd[1]: Stopped go-librespot Daemon. Mar 04 20:03:02 dac.x2-nvme systemd[1]: Started go-librespot Daemon. Mar 04 20:03:02 dac.x2-nvme go-librespot[16043]: go-librespot daemon starting... Mar 04 20:03:02 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:02+08:00" level=info msg="running go-librespot 0.2.0" Mar 04 20:03:02 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:02+08:00" level=debug msg="app state loaded" Mar 04 20:03:02 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:02+08:00" level=debug msg="stored credentials not found" Mar 04 20:03:02 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:02+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 20:03:03 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:03+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 04 20:03:03 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:03+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 04 20:03:03 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:03+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 04 20:03:03 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:03+08:00" level=info msg="zeroconf server listening on port 37105" Mar 04 20:03:04 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:04+08:00" level=debug msg="obtained new client token: AAAldzur6dlQiMX//APRoHTWjZrtgvcd5fCsrShcG7Yu67Gno9z/KI5GdvvG//6uEbPuR0mz3JVBKs64s/tmkcAMPRqLU7k5ddlg2dx5h81MPDRT0C4OH9d6BQSOS59k+wwaZskJnDeekCAQPrYGOaOCqyftv4M261rvEcaMjkS+f2rpjJ8CCDDMnz8p7jB+YWS1UTQfXhj8mAfMYjZVHDqnAham58Lh7/Y+MlXCmDinJPw2DiMj1qxy5A==" Mar 04 20:03:04 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:04+08:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused" Mar 04 20:03:04 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:04 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:04+08:00" level=debug msg="new websocket client" Mar 04 20:03:04 dac.x2-nvme volumio[1363]: info: Connection to go-librespot Websocket established Mar 04 20:03:04 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:04+08:00" level=debug msg="connected to ap-gae2.spotify.com:443" Mar 04 20:03:04 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:04+08:00" level=debug msg="completed keyexchange" Mar 04 20:03:04 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:04+08:00" level=debug msg="completed challenge" Mar 04 20:03:04 dac.x2-nvme go-librespot[16043]: time="2025-03-04T20:03:04+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 04 20:03:04 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 04 20:03:04 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 04 20:03:04 dac.x2-nvme volumio[1363]: info: Connection to go-librespot Websocket closed Mar 04 20:03:06 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:03:07 dac.x2-nvme volumio[1363]: info: Getting Spotify volume Mar 04 20:03:07 dac.x2-nvme volumio[1363]: (node:1363) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:07 dac.x2-nvme volumio[1363]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 04 20:03:07 dac.x2-nvme volumio[1363]: (node:1363) 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: 119) Mar 04 20:03:07 dac.x2-nvme volumio[1363]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Mar 04 20:03:07 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioGetState Mar 04 20:03:07 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:03:07 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:07 dac.x2-nvme volumio[1363]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:07 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 04 20:03:07 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 263. Mar 04 20:03:07 dac.x2-nvme systemd[1]: Stopped go-librespot Daemon. Mar 04 20:03:07 dac.x2-nvme systemd[1]: Started go-librespot Daemon. Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: go-librespot daemon starting... Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=info msg="running go-librespot 0.2.0" Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=debug msg="app state loaded" Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=debug msg="stored credentials not found" Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 04 20:03:07 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:07+08:00" level=info msg="zeroconf server listening on port 44459" Mar 04 20:03:09 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:09+08:00" level=debug msg="obtained new client token: AABnHu6vduZ/1KyHUdsZ5sMNOLJLJ+dSVvwzMWBXZG4xutZR51nsMrINCdf9L7LWTicra7JSoQbO0GKMa5ScDnTjo82MRmik122/SL3qg+9bqSGmzJJZ0H6u95XHaa1GZW5QHcYfXk4nBSJen8lNTAxMIT8w9DT85ilUkK3kjJFEnUghuceQQJER9EuU1nLvvU+yjgNBhjIZXnzTR/iOlFV2fMxrsQWt65fV+SAlj+8uMuRnd0+3lheiUQ==" Mar 04 20:03:10 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:10+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 04 20:03:10 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:10+08:00" level=debug msg="completed keyexchange" Mar 04 20:03:10 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:10+08:00" level=debug msg="completed challenge" Mar 04 20:03:10 dac.x2-nvme go-librespot[16064]: time="2025-03-04T20:03:10+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 04 20:03:10 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 04 20:03:10 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 04 20:03:10 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:10 dac.x2-nvme volumio[1363]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:11 dac.x2-nvme volumio[1363]: info: MyVolumio login type: Token Mar 04 20:03:13 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:13 dac.x2-nvme volumio[1363]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:13 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 04 20:03:13 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 264. Mar 04 20:03:13 dac.x2-nvme systemd[1]: Stopped go-librespot Daemon. Mar 04 20:03:13 dac.x2-nvme systemd[1]: Started go-librespot Daemon. Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: go-librespot daemon starting... Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=info msg="running go-librespot 0.2.0" Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=debug msg="app state loaded" Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=debug msg="stored credentials not found" Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 20:03:13 dac.x2-nvme volumiologrotate[755]: ls: cannot access '/var/log/samba/log.wb-DAC.X2': No such file or directory Mar 04 20:03:13 dac.x2-nvme volumiologrotate[755]: ls: cannot access 'NVME': No such file or directory Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 04 20:03:13 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:13+08:00" level=info msg="zeroconf server listening on port 37387" Mar 04 20:03:14 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:14+08:00" level=debug msg="obtained new client token: AAAYdBk6JmjNPDtZwhHBLWrQRilEiOCLTDeVDQ63UWiA4ycZbeYacEwxCzE212tyjE5/KKe3ZD6uUFhtjmChClguEISIJdOXXr7HC4TKFsKkLfic2hKX7ayXL+cXDiij+tryKQ9u7cAN7U0RWfOxknC2HP4l4paFwvXvIgd2l0PnnCTFtJ0bVGzIcdHSLAEyTFiDsDpRPDWycsPRRUAitdSXFx+1pZ1U/7SIru6ZKIV0RytdXqbLfLFw2Q==" Mar 04 20:03:14 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:14+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 04 20:03:14 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:14+08:00" level=debug msg="completed keyexchange" Mar 04 20:03:14 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:14+08:00" level=debug msg="completed challenge" Mar 04 20:03:14 dac.x2-nvme go-librespot[16099]: time="2025-03-04T20:03:14+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 04 20:03:14 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 04 20:03:14 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 04 20:03:14 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:03:16 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:16 dac.x2-nvme volumio[1363]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:17 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 04 20:03:17 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 265. Mar 04 20:03:17 dac.x2-nvme systemd[1]: Stopped go-librespot Daemon. Mar 04 20:03:17 dac.x2-nvme systemd[1]: Started go-librespot Daemon. Mar 04 20:03:17 dac.x2-nvme go-librespot[16163]: go-librespot daemon starting... Mar 04 20:03:17 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:17+08:00" level=info msg="running go-librespot 0.2.0" Mar 04 20:03:17 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:17+08:00" level=debug msg="app state loaded" Mar 04 20:03:17 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:17+08:00" level=debug msg="stored credentials not found" Mar 04 20:03:17 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:17+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=info msg="zeroconf server listening on port 41777" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=debug msg="obtained new client token: AAAjW8Atoi91kHJD1iA3UDSwXLSyocH8jcelccPGvFt1w9bbKxDIoPgblYmUbbz9MKivQd/oONIchXqdS2qHh4uff08nDwq1v2fhMer3cZJkK+kBGFXAuAi+5dwDfIFTyvT5pRp34QJtOFjgeLKp8uW3ncfW9L0CLrdWfgWsU5HbBt+vc4cJYODZg2nNip+C700VybC+gL/kzaPKcM8duuyFpvS0of+XFkzPnxmJhr4YUv4UiZ+ANqfJYg==" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=debug msg="completed keyexchange" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=debug msg="completed challenge" Mar 04 20:03:18 dac.x2-nvme go-librespot[16163]: time="2025-03-04T20:03:18+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 04 20:03:18 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 04 20:03:18 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 04 20:03:19 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:19 dac.x2-nvme volumio[1363]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:20 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioGetState Mar 04 20:03:20 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:03:21 dac.x2-nvme volumio[1363]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Engine version: 3 Transport: polling Total Clients: 8 Mar 04 20:03:21 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioGetState Mar 04 20:03:21 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:03:21 dac.x2-nvme volumio[1363]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/Dua%20Lipa/Dua%20Lipa%20Live%20from%20the%20Royal%20Albert%20Hall/01824ad2-8ce7-4d60-aafa-6dae1d4d808a.png' Mar 04 20:03:22 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 04 20:03:22 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 266. Mar 04 20:03:22 dac.x2-nvme systemd[1]: Stopped go-librespot Daemon. Mar 04 20:03:22 dac.x2-nvme systemd[1]: Started go-librespot Daemon. Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: go-librespot daemon starting... Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=info msg="running go-librespot 0.2.0" Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=debug msg="app state loaded" Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=debug msg="stored credentials not found" Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 20:03:22 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=debug msg="new websocket client" Mar 04 20:03:22 dac.x2-nvme volumio[1363]: info: Connection to go-librespot Websocket established Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+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]" Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Mar 04 20:03:22 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:22+08:00" level=info msg="zeroconf server listening on port 40909" Mar 04 20:03:22 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:03:23 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:23+08:00" level=debug msg="obtained new client token: AABHKgmfIXFKXqQPn7+nXdhfOnYnf3sGMBKsF9tvDi2bRcdWMSu6EqLNvQb795Nz5Vcc7iXD/tb8DmZ2UF2vnYPRzFoJ32rI5TSWicD+fnLIE5u6lF3++lhW0Rjo69Ilfy2QTisjnbfzTO0AcKyKy8kXnaIc7uLJoDYeRvAoJpSPUfgXkaLmdkWzG2NCMGbFx0xyAmA8/ky9OiZShQifCUBsgOhAtgXl6M3BDR2rKW3/+vIPv4m60Yk=" Mar 04 20:03:24 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:24+08:00" level=debug msg="connected to ap-gae2.spotify.com:4070" Mar 04 20:03:24 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:24+08:00" level=debug msg="completed keyexchange" Mar 04 20:03:24 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:24+08:00" level=debug msg="completed challenge" Mar 04 20:03:24 dac.x2-nvme go-librespot[16214]: time="2025-03-04T20:03:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: accesspoint login failed: BadCredentials " Mar 04 20:03:24 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 04 20:03:24 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 04 20:03:24 dac.x2-nvme volumio[1363]: info: Connection to go-librespot Websocket closed Mar 04 20:03:25 dac.x2-nvme volumio[1363]: info: Getting Spotify volume Mar 04 20:03:25 dac.x2-nvme volumio[1363]: (node:1363) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:25 dac.x2-nvme volumio[1363]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 04 20:03:25 dac.x2-nvme volumio[1363]: (node:1363) 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: 120) Mar 04 20:03:25 dac.x2-nvme volumio[1363]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 04 20:03:25 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioGetState Mar 04 20:03:25 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:03:27 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:27 dac.x2-nvme volumio[1363]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 04 20:03:27 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 04 20:03:27 dac.x2-nvme systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 267. Mar 04 20:03:27 dac.x2-nvme systemd[1]: Stopped go-librespot Daemon. Mar 04 20:03:27 dac.x2-nvme systemd[1]: Started go-librespot Daemon. Mar 04 20:03:27 dac.x2-nvme go-librespot[16236]: go-librespot daemon starting... Mar 04 20:03:27 dac.x2-nvme go-librespot[16236]: time="2025-03-04T20:03:27+08:00" level=info msg="running go-librespot 0.2.0" Mar 04 20:03:27 dac.x2-nvme go-librespot[16236]: time="2025-03-04T20:03:27+08:00" level=debug msg="app state loaded" Mar 04 20:03:27 dac.x2-nvme go-librespot[16236]: time="2025-03-04T20:03:27+08:00" level=debug msg="stored credentials not found" Mar 04 20:03:27 dac.x2-nvme go-librespot[16236]: time="2025-03-04T20:03:27+08:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 04 20:03:30 dac.x2-nvme volumio[1363]: info: Initializing connection to go-librespot Websocket Mar 04 20:03:30 dac.x2-nvme volumio[1363]: info: Connection to go-librespot Websocket established Mar 04 20:03:30 dac.x2-nvme go-librespot[16236]: time="2025-03-04T20:03:30+08:00" level=debug msg="new websocket client" Mar 04 20:03:31 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:03:33 dac.x2-nvme volumio[1363]: info: Getting Spotify volume Mar 04 20:03:33 dac.x2-nvme volumio[1363]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Mar 04 20:03:33 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioGetState Mar 04 20:03:33 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:03:39 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:03:41 dac.x2-nvme volumio[1363]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Mar 04 20:03:41 dac.x2-nvme volumio[1363]: info: Retrying Login Due to Network Error Mar 04 20:03:47 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:03:51 dac.x2-nvme volumio[1363]: info: MyVolumio login type: Token Mar 04 20:03:55 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 1 Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: Prefetching next song Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: DOING PREFETCH IN MPD Mar 04 20:03:57 dac.x2-nvme volumio[1363]: verbose: ControllerMpd::sendMpdCommand add "NAS/CloudMusic/Volumio/Dua Lipa - Live from the Royal Albert Hall/02 - End Of An Era (Live from the Royal Albert Hall).flac" Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: Mar 04 20:03:57 dac.x2-nvme volumio[1363]: ---------------------------- MPD announces system playlist update Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: Ignoring MPD Status Update Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: sendMpdCommand add "NAS/CloudMusic/Volumio/Dua Lipa - Live from the Royal Albert Hall/02 - End Of An Era (Live from the Royal Albert Hall).flac" took 1 milliseconds Mar 04 20:03:57 dac.x2-nvme volumio[1363]: verbose: ControllerMpd::sendMpdCommand consume 1 Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: ------------------------------ 2ms Mar 04 20:03:57 dac.x2-nvme volumio[1363]: info: sendMpdCommand consume 1 took 1 milliseconds Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: Mar 04 20:04:01 dac.x2-nvme volumio[1363]: ---------------------------- MPD announces system playlist update Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: Ignoring MPD Status Update Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: Mar 04 20:04:01 dac.x2-nvme volumio[1363]: ---------------------------- MPD announces state update: player Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: ControllerMpd::getState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: verbose: ControllerMpd::sendMpdCommand status Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: ------------------------------ 2ms Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: sendMpdCommand status took 1 milliseconds Mar 04 20:04:01 dac.x2-nvme volumio[1363]: verbose: ControllerMpd::parseState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: sendMpdCommand playlistinfo took 1 milliseconds Mar 04 20:04:01 dac.x2-nvme volumio[1363]: verbose: ControllerMpd::parseTrackInfo Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: ControllerMpd::pushState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::servicePushState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:04:01 dac.x2-nvme volumio[1363]: verbose: STATE SERVICE {"status":"play","position":0,"seek":42,"duration":240,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1392 Kbps","isStreaming":false,"title":"End Of An Era (Live from the Royal Albert Hall)","artist":"Dua Lipa","album":"Dua Lipa Live from the Royal Albert Hall","uri":"NAS/CloudMusic/Volumio/Dua Lipa - Live from the Royal Albert Hall/02 - End Of An Era (Live from the Royal Albert Hall).flac","trackType":"flac"} Mar 04 20:04:01 dac.x2-nvme volumio[1363]: verbose: CURRENT POSITION 0 Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreStateMachine::syncState stateService play Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreStateMachine::syncState currentStatus play Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: Received an update from plugin. extracting info from payload Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreStateMachine::pushState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioPushState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreStateMachine::pushState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 0 Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioPushState Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: ------------------------------ 13ms Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CoreStateMachine::startPlaybackTimer Mar 04 20:04:01 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 1 Mar 04 20:04:02 dac.x2-nvme volumio[1363]: info: CoreStateMachine::pushState Mar 04 20:04:02 dac.x2-nvme volumio[1363]: info: CorePlayQueue::getTrack 1 Mar 04 20:04:02 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 04 20:04:02 dac.x2-nvme volumio[1363]: info: CoreCommandRouter::volumioPushState Mar 04 20:04:03 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:04:12 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:04:13 dac.x2-nvme volumiologrotate[755]: ls: cannot access '/var/log/samba/log.wb-DAC.X2': No such file or directory Mar 04 20:04:13 dac.x2-nvme volumiologrotate[755]: ls: cannot access 'NVME': No such file or directory Mar 04 20:04:20 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:04:21 dac.x2-nvme volumio[1363]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Mar 04 20:04:21 dac.x2-nvme volumio[1363]: info: Retrying Login Due to Network Error Mar 04 20:04:28 dac.x2-nvme wpa_supplicant[1182]: wlan0: Failed to initiate sched scan Mar 04 20:04:30 dac.x2-nvme volumio[1363]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 04 20:04:30 dac.x2-nvme volumio[1363]: Error: connect ETIMEDOUT 65.49.26.99:443 Mar 04 20:04:30 dac.x2-nvme volumio[1363]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Mar 04 20:04:30 dac.x2-nvme volumio[1363]: errno: -110, Mar 04 20:04:30 dac.x2-nvme volumio[1363]: code: 'ETIMEDOUT', Mar 04 20:04:30 dac.x2-nvme volumio[1363]: syscall: 'connect', Mar 04 20:04:30 dac.x2-nvme volumio[1363]: address: '65.49.26.99', Mar 04 20:04:30 dac.x2-nvme volumio[1363]: port: 443 Mar 04 20:04:30 dac.x2-nvme volumio[1363]: } Mar 04 20:04:30 dac.x2-nvme volumio[1363]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 04 20:04:30 dac.x2-nvme sudo[16555]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-04 20:03 Mar 04 20:04:30 dac.x2-nvme sudo[16555]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"