-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Fri 2025-01-17 22:27:09 CET. -- Jan 17 22:26:00 volumio go-librespot[16181]: time="2025-01-17T22:26:00+01:00" level=debug msg="completed challenge" Jan 17 22:26:00 volumio go-librespot[16181]: time="2025-01-17T22:26:00+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:01 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:02 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 694. Jan 17 22:26:03 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:03 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:03 volumio go-librespot[16193]: Librespot-go daemon starting... Jan 17 22:26:03 volumio go-librespot[16193]: time="2025-01-17T22:26:03+01:00" level=info msg="generated new device id: f3b73898f63f507b76c5f1b4ce470c15c34f2324" Jan 17 22:26:03 volumio go-librespot[16193]: time="2025-01-17T22:26:03+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:03 volumio go-librespot[16193]: time="2025-01-17T22:26:03+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:03 volumio go-librespot[16193]: time="2025-01-17T22:26:03+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:03 volumio go-librespot[16193]: time="2025-01-17T22:26:03+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:03 volumio go-librespot[16193]: time="2025-01-17T22:26:03+01:00" level=debug msg="zeroconf server listening on port 43451" Jan 17 22:26:04 volumio go-librespot[16193]: time="2025-01-17T22:26:04+01:00" level=debug msg="obtained new client token: AABGApnmQ7H5fFkNiuKWcGqmxtJi2TqqUgHZz+TFSBK4BxGS4UjWYdOr/mKX/z1/lHq72zIDvDYMIsddlarwqrP48YsOTvVxWhHA+4Jm/amfQicaOPIcF7731m6PwLVFL5sbAxPiPlogHI/MUKisMuckhovWmHOGaud+wdnneeaSCsziy/HyBwRNAP6HwgurslQJsa1JkUPupXcJincO2gUXku3+Pe7OzUG9lWlSaAJe2WfjjaC5GCpH2oKpCZM=" Jan 17 22:26:04 volumio go-librespot[16193]: time="2025-01-17T22:26:04+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:04 volumio go-librespot[16193]: time="2025-01-17T22:26:04+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:04 volumio go-librespot[16193]: time="2025-01-17T22:26:04+01:00" level=debug msg="completed challenge" Jan 17 22:26:04 volumio go-librespot[16193]: time="2025-01-17T22:26:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:05 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:05 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:07 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 695. Jan 17 22:26:07 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:07 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:07 volumio go-librespot[16219]: Librespot-go daemon starting... Jan 17 22:26:07 volumio go-librespot[16219]: time="2025-01-17T22:26:07+01:00" level=info msg="generated new device id: ca997bff27747e0eb6ef953080f4873e34e9f3d9" Jan 17 22:26:07 volumio go-librespot[16219]: time="2025-01-17T22:26:07+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:07 volumio go-librespot[16219]: time="2025-01-17T22:26:07+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:07 volumio go-librespot[16219]: time="2025-01-17T22:26:07+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:07 volumio go-librespot[16219]: time="2025-01-17T22:26:07+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:07 volumio go-librespot[16219]: time="2025-01-17T22:26:07+01:00" level=debug msg="zeroconf server listening on port 41245" Jan 17 22:26:08 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:08 volumio go-librespot[16219]: time="2025-01-17T22:26:08+01:00" level=debug msg="new websocket client" Jan 17 22:26:08 volumio volumio[986]: info: Connection to go-librespot Websocket established Jan 17 22:26:08 volumio go-librespot[16219]: time="2025-01-17T22:26:08+01:00" level=debug msg="obtained new client token: AAAKK2svOgTBRpouFMVU93JJ8ASX8VEEqNTvtAdtTfGJgFVRqBzlnmiTSpwTQO9Ahpzm75IEemYJwypnGTVdhW0hW5gqkqre/PX00zikwpZV+kEZMNYupuSBytk4UhiiVgDBPSxAa+TvMeQhTCDGyNYfGg5OAZqakNlln8jbjPuUNB0tJKUq1LiQgp9idiGsp9gf6MivI/mFOIFnT96rd7+Dq6ODzRENwumJUEminO2Ve+84qQ53OOp24Quo" Jan 17 22:26:08 volumio go-librespot[16219]: time="2025-01-17T22:26:08+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:08 volumio go-librespot[16219]: time="2025-01-17T22:26:08+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:08 volumio go-librespot[16219]: time="2025-01-17T22:26:08+01:00" level=debug msg="completed challenge" Jan 17 22:26:08 volumio go-librespot[16219]: time="2025-01-17T22:26:08+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:08 volumio volumio[986]: info: Connection to go-librespot Websocket closed Jan 17 22:26:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:11 volumio volumio[986]: info: Getting Spotify volume Jan 17 22:26:11 volumio volumio[986]: (node:986) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:11 volumio volumio[986]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 17 22:26:11 volumio volumio[986]: (node:986) 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: 185) Jan 17 22:26:11 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jan 17 22:26:11 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Jan 17 22:26:11 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:11 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:11 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 696. Jan 17 22:26:11 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:12 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:12 volumio go-librespot[16230]: Librespot-go daemon starting... Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=info msg="generated new device id: bb92db02e69434b488da3a3d14374f5538ea6b38" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="zeroconf server listening on port 37311" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="obtained new client token: AADzL5SgspGlANqxcnu/O6M8mOuC4/qR6wWJ3eSfev1tr14kkBZqfqf3E83dHm6tCKDfobx+f5S3OdAF1yoy25f03/2GIaCGtppu0qKdUR/Fmsy9C/35vusvPCuTZdbz+LCIOULkpz4cn4WkJVsyjcworiNSWgdHzQMpw7L6QsqFo2PzkR/zoyoCLv6xOc8ubaa59J1lApDuNkVr5PhwXnOxc40aPvMq/xxcpo80ZMPuwSFF+ebRVKOwgTnKyy8=" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=debug msg="completed challenge" Jan 17 22:26:12 volumio go-librespot[16230]: time="2025-01-17T22:26:12+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:14 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:14 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 697. Jan 17 22:26:15 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:16 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:16 volumio go-librespot[16252]: Librespot-go daemon starting... Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=info msg="generated new device id: e3fdd33fb078b71e3b7ea6b5ab986f88927dd4af" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="zeroconf server listening on port 40209" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="obtained new client token: AACWFeh9evU55tCKqED799R5U7ld2hbT5jLWpuiSwTsg4pj/8ZdPMC6ar+bJn2S9xn2PyOOfs6Xbrx9sv9XbSf2XBOAkqWl0NMMFoZyk6ViThtoBaBpbd+haFyP3nw4uJMD8jBvhM02UUXflnhwWDjzrv9pZ5eOhUut3EbHZsJsjDzJn94B0VT4pNcoBQh8wx1MYYVEdKGHpu9lv+HT80DTzLhXjKZbK74F0JRRvbtOJRDLZ/i1Hj4HadADaXHQ=" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=debug msg="completed challenge" Jan 17 22:26:16 volumio go-librespot[16252]: time="2025-01-17T22:26:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:17 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:17 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 698. Jan 17 22:26:19 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:20 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:20 volumio go-librespot[16263]: Librespot-go daemon starting... Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=info msg="generated new device id: 5c36d323bf5af64292230d8b6c57fe1e5876dc12" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="zeroconf server listening on port 41519" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="obtained new client token: AACFDgSk4bOXZQKk/yyL0CTUUIuY4CIWijACazVmutLGPtBzg8rvKb00lHfenOQjwQjnWgioU3kb774VnQweJeP876hhcBYHYOcrz2I/svna7YYTG6g+rwWBpgBVGClVL7KZFZ3b+LBS1bRB72UYvSDVj4xEPPRtOplBt0fVq2YMXvUpvbyzR8Oxt2ho9N2VYnljvSNcPAuA59d/XEEzb82HhAmVj7IyqL5Jc1TkKLgobfd9oydT28lYwsKB0Nw=" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:20 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="new websocket client" Jan 17 22:26:20 volumio volumio[986]: info: Connection to go-librespot Websocket established Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=debug msg="completed challenge" Jan 17 22:26:20 volumio go-librespot[16263]: time="2025-01-17T22:26:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:20 volumio volumio[986]: info: Connection to go-librespot Websocket closed Jan 17 22:26:21 volumio volumio[986]: info: Preload queue cleared Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::ClearQueue Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::stop Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::stPlaybackTimer Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::updateTrackBlock Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrackBlock Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::serviceStop Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::serviceStop Jan 17 22:26:21 volumio volumio[986]: info: [1737149181210] ControllerWebradio::stop Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand stop Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::clearPlayQueue Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::saveQueue Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPushQueue Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::addQueueItems Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::addQueueItems Jan 17 22:26:21 volumio volumio[986]: info: Preload queue cleared Jan 17 22:26:21 volumio volumio[986]: info: Adding Item to queue: http://stream.radioparadise.com/flacm Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPushQueue Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::saveQueue Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::updateTrackBlock Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrackBlock Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPlay Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::play index 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::stop Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::play index undefined Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::startPlaybackTimer Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: info: [1737149181222] ControllerWebradio::clearAddPlayTrack Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand stop Jan 17 22:26:21 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:21 volumio volumio[986]: info: Jan 17 22:26:21 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand stop took 16 milliseconds Jan 17 22:26:21 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand stop took 4 milliseconds Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand clear Jan 17 22:26:21 volumio volumio[986]: info: Jan 17 22:26:21 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:21 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand status took 1 milliseconds Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand clear took 1 milliseconds Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand load "http://stream.radioparadise.com/flacm" Jan 17 22:26:21 volumio volumio[986]: error: updateQueue error: null Jan 17 22:26:21 volumio volumio[986]: info: ------------------------------ 1ms Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:21 volumio volumio[986]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Jan 17 22:26:21 volumio volumio[986]: info: ------------------------------ 4ms Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand add "http://stream.radioparadise.com/flacm" Jan 17 22:26:21 volumio volumio[986]: info: Jan 17 22:26:21 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:21 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand add "http://stream.radioparadise.com/flacm" took 1 milliseconds Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService mpd Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand play Jan 17 22:26:21 volumio volumio[986]: info: ------------------------------ 1ms Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand play took 1 milliseconds Jan 17 22:26:21 volumio volumio[986]: info: Jan 17 22:26:21 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:21 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:21 volumio volumio[986]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jan 17 22:26:21 volumio volumio[986]: info: FusionDsp - ---- read samplerate from file: 44100 Jan 17 22:26:21 volumio volumio[986]: info: camilladsp stopping service pid 15948... Jan 17 22:26:21 volumio kernel: bcm2835_audio bcm2835_audio: failed to close VCHI service connection (status=-11) Jan 17 22:26:21 volumio volumio[986]: info: camilladsp service terminated, instance 1 Jan 17 22:26:21 volumio volumio[986]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jan 17 22:26:21 volumio volumio[986]: info: camilladsp service started and running in background, instance 1 Jan 17 22:26:21 volumio volumio[986]: info: Jan 17 22:26:21 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand status took 38 milliseconds Jan 17 22:26:21 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand status took 2 milliseconds Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand playlistinfo took 2 milliseconds Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:21 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"flacm","artist":null,"album":null,"uri":"http://stream.radioparadise.com/flacm","trackType":"com/flacm"} Jan 17 22:26:21 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus stop Jan 17 22:26:21 volumio volumio[986]: info: ------------------------------ 43ms Jan 17 22:26:21 volumio volumio[986]: info: camilladsp spawned new process with pid 16275, instance 1, run: true Jan 17 22:26:21 volumio volumio[986]: info: Jan 17 22:26:21 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:21 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:21 volumio volumio[986]: info: Jan 17 22:26:21 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand playlistinfo took 20 milliseconds Jan 17 22:26:21 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:21 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"flacm","artist":null,"album":null,"uri":"http://stream.radioparadise.com/flacm","trackType":"com/flacm"} Jan 17 22:26:21 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus play Jan 17 22:26:21 volumio volumio[986]: info: Received an update from plugin. extracting info from payload Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:21 volumio volumio[986]: info: ------------------------------ 48ms Jan 17 22:26:21 volumio volumio[986]: info: ------------------------------ 26ms Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand status took 25 milliseconds Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:21 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:21 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:21 volumio volumio[986]: info: sendMpdCommand playlistinfo took 4 milliseconds Jan 17 22:26:21 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:21 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"flacm","artist":"Radio Paradise (flac) - playlist: radioparadise.com","album":null,"uri":"http://stream.radioparadise.com/flacm","trackType":"com/flacm"} Jan 17 22:26:21 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus play Jan 17 22:26:21 volumio volumio[986]: info: Received an update from plugin. extracting info from payload Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:21 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:21 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:21 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:21 volumio volumio[986]: info: ------------------------------ 43ms Jan 17 22:26:21 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:21 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:23 volumio volumio[986]: info: Getting Spotify volume Jan 17 22:26:23 volumio volumio[986]: (node:986) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:23 volumio volumio[986]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 17 22:26:23 volumio volumio[986]: (node:986) 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: 186) Jan 17 22:26:23 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 17 22:26:23 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Jan 17 22:26:23 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:23 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:24 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:24 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 699. Jan 17 22:26:24 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:24 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:24 volumio go-librespot[16282]: Librespot-go daemon starting... Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=info msg="generated new device id: 16df751fe7c2eee6d5dfa31d5c97bac9b231b78f" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=debug msg="zeroconf server listening on port 39637" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=debug msg="obtained new client token: AAD8CuPKufV6OqQYhw6GdkEbLI+gVYCpDF+1//M//CVROOIUwOGrQI2KDx92L5+BRbg22a/Grw4t0pg8Jy7klXNS4C9jFmoWL2MaMXr59A24R0O8yK280Gwdw/38OFXWs9O6+K/TFtNuyntBxRlpIyqtwirJXhPWo0co1kPUmVY3MSPV+cEX4TADXrIpvoS1xOV7eoUPyw85iYahvvCYx0EsFNvK6nqzoeAR3tz2hw9L0oDLua97k2xAKA4Senc=" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:24 volumio go-librespot[16282]: time="2025-01-17T22:26:24+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:25 volumio go-librespot[16282]: time="2025-01-17T22:26:25+01:00" level=debug msg="completed challenge" Jan 17 22:26:25 volumio go-librespot[16282]: time="2025-01-17T22:26:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:26 volumio volumio[986]: info: Jan 17 22:26:26 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:26 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:26 volumio volumio[986]: info: Jan 17 22:26:26 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:26 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:26 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:26 volumio volumio[986]: info: ------------------------------ 2ms Jan 17 22:26:26 volumio volumio[986]: info: sendMpdCommand status took 1 milliseconds Jan 17 22:26:26 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:26 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:26 volumio volumio[986]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 17 22:26:26 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:26 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:26 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:26 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:26 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":5451,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Police - Walking in Your Footsteps","artist":"Radio Paradise (flac) - playlist: radioparadise.com","album":null,"uri":"http://stream.radioparadise.com/flacm","trackType":"com/flacm"} Jan 17 22:26:26 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:26 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:26 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus play Jan 17 22:26:26 volumio volumio[986]: info: Received an update from plugin. extracting info from payload Jan 17 22:26:26 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 17 22:26:26 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:26 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:26 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:26 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:26 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:26 volumio volumio[986]: info: ------------------------------ 19ms Jan 17 22:26:26 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:27 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:27 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 700. Jan 17 22:26:28 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:28 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:28 volumio go-librespot[16304]: Librespot-go daemon starting... Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=info msg="generated new device id: ec61c3342e2d2841a1c1eaf20851e7bdb4a98eba" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=debug msg="zeroconf server listening on port 36131" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=debug msg="obtained new client token: AACmrcEioGWlaNZQLH0Ffwc/GKiVPJrIwh48tcYmYj4mBRnda6lkDHv5nD98Ju0tF2VXWjPs1ufF0F69ev9k9b9d2bwRmcKJcwmWD3NQ+/xA6u81lkvhOMHknUmClUj6zgg81b6zUBr8V5Yzv3a2RvOcL7UHKeESSVBuoD//5YBht8oQK4a6Vn4Glg28drTfGaTy+md3y8vHY4TE+IXgzi5EtXUbBb0g/HfEJCl7CNBRZRIXa1TNdfPLtYzJ2Oo=" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:28 volumio go-librespot[16304]: time="2025-01-17T22:26:28+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:29 volumio go-librespot[16304]: time="2025-01-17T22:26:29+01:00" level=debug msg="completed challenge" Jan 17 22:26:29 volumio go-librespot[16304]: time="2025-01-17T22:26:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:30 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:30 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 701. Jan 17 22:26:32 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:32 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:32 volumio go-librespot[16316]: Librespot-go daemon starting... Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=info msg="generated new device id: 3e4386b7e8fa9770f9b67959e06837087e35f92e" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=debug msg="zeroconf server listening on port 42793" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=debug msg="obtained new client token: AADXkqoKd27SHyFH9lHRTcgR9ohCKTVg/YmTjJ91pzuevcz/YsjwBerWpGHOEAqfBqBYKtQ2gLNUMmxX7rWwQSvEzISH7gOLV5kAWXKW9Chm8LAktY4V9ttcp7NF6UKYY85FfjEB7vp2VJOGEWBNwhwb+zMyD0ZQ8CXv+kP8ust6cYQv+3zO+ilGfonO17caOtcOeAvQOsIxJD6CQR4uHwrg00+B4BllwX9EdIi3/c8cLP9n4stRh/YRFcr5Xd8=" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:32 volumio go-librespot[16316]: time="2025-01-17T22:26:32+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:33 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:33 volumio go-librespot[16316]: time="2025-01-17T22:26:33+01:00" level=debug msg="new websocket client" Jan 17 22:26:33 volumio volumio[986]: info: Connection to go-librespot Websocket established Jan 17 22:26:33 volumio go-librespot[16316]: time="2025-01-17T22:26:33+01:00" level=debug msg="completed challenge" Jan 17 22:26:33 volumio go-librespot[16316]: time="2025-01-17T22:26:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:33 volumio volumio[986]: info: Connection to go-librespot Websocket closed Jan 17 22:26:36 volumio volumio[986]: info: Getting Spotify volume Jan 17 22:26:36 volumio volumio[986]: (node:986) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:36 volumio volumio[986]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 17 22:26:36 volumio volumio[986]: (node:986) 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: 187) Jan 17 22:26:36 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 17 22:26:36 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Jan 17 22:26:36 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:36 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:36 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 702. Jan 17 22:26:36 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:36 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:36 volumio go-librespot[16338]: Librespot-go daemon starting... Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=info msg="generated new device id: 7bdcd69e9afaac2ef99a7809e1a9b664c015d6ae" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=debug msg="zeroconf server listening on port 34825" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=debug msg="obtained new client token: AAD5T3dQ6FnKLMoZGsZZcZ/sFNAnzKYxY5BYfUvPwXam+KlduHBYj63l68sO6/V/F51atwoaxWK8DmpJXYjUZp26+OPRvXoJ65pVuC79dpKBYGgv5zY+VwjYlj2pUbjekoM11E/Z7W8yIufuqsGM2Av3QlBZnW5BvY6MVRW0p2piU9MfosOg/BMpLftdJIOKYVNG9ZjVR8fBbLc2J8TjMOHF1mzr/gyGu3gZhg1dMvr0P9+mBeI6EHb5kbTEwKY=" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070 (error: dial tcp 34.158.1.133:4070: connect: connection refused), retrying with a different AP" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=info msg="connected to ap-gew4.spotify.com:443" Jan 17 22:26:36 volumio go-librespot[16338]: time="2025-01-17T22:26:36+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:37 volumio go-librespot[16338]: time="2025-01-17T22:26:37+01:00" level=debug msg="completed challenge" Jan 17 22:26:37 volumio go-librespot[16338]: time="2025-01-17T22:26:37+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:39 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:39 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:40 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 703. Jan 17 22:26:40 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:40 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:40 volumio go-librespot[16350]: Librespot-go daemon starting... Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=info msg="generated new device id: a8ae50899e030dd7b08c1cde16d9e82e5f6b6f4d" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=debug msg="zeroconf server listening on port 35401" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=debug msg="obtained new client token: AABAAvk5qXb9/02SU5qfqVaDMSqiZZl1sEFXPOwHbQPckykU4LJG8gqnEj+5xUkdy82H5Vnh/E7qmNek5wl+7mIpNpmfGMjsFy2LNSRpNIhqluYu37BfI0JA+ZodYds/0we7ni3gZ5zhNpPGvTq8VXcCxc3jmv1JWi67PzzUOPoGMIe8cPEO1Bdk6dQcKDca5MdacgmbTc8ElE4znRO8HivHu+2xHEie77NQ+EFtxfWP+X+xGVrfHXOj6KSypG0=" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:40 volumio go-librespot[16350]: time="2025-01-17T22:26:40+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:41 volumio go-librespot[16350]: time="2025-01-17T22:26:41+01:00" level=debug msg="completed challenge" Jan 17 22:26:41 volumio go-librespot[16350]: time="2025-01-17T22:26:41+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:41 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:41 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:41 volumio volumio[986]: info: Preload queue cleared Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::ClearQueue Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::stop Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::stPlaybackTimer Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::updateTrackBlock Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrackBlock Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::serviceStop Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::serviceStop Jan 17 22:26:41 volumio volumio[986]: info: [1737149201720] ControllerWebradio::stop Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand stop Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::clearPlayQueue Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::saveQueue Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPushQueue Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::addQueueItems Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::addQueueItems Jan 17 22:26:41 volumio volumio[986]: info: Preload queue cleared Jan 17 22:26:41 volumio volumio[986]: info: Adding Item to queue: http://stream.radioparadise.com/world-etc-flacm Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPushQueue Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::saveQueue Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::updateTrackBlock Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrackBlock Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPlay Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::play index 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::stop Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::play index undefined Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::startPlaybackTimer Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: info: [1737149201731] ControllerWebradio::clearAddPlayTrack Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand stop Jan 17 22:26:41 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:41 volumio volumio[986]: info: Jan 17 22:26:41 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand stop took 19 milliseconds Jan 17 22:26:41 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand stop took 8 milliseconds Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand clear Jan 17 22:26:41 volumio volumio[986]: info: Jan 17 22:26:41 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:41 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand status took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand clear took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand load "http://stream.radioparadise.com/world-etc-flacm" Jan 17 22:26:41 volumio volumio[986]: error: updateQueue error: null Jan 17 22:26:41 volumio volumio[986]: info: ------------------------------ 1ms Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:41 volumio volumio[986]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Jan 17 22:26:41 volumio volumio[986]: info: ------------------------------ 4ms Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand add "http://stream.radioparadise.com/world-etc-flacm" Jan 17 22:26:41 volumio volumio[986]: info: Jan 17 22:26:41 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:41 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand add "http://stream.radioparadise.com/world-etc-flacm" took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::setConsumeUpdateService mpd Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand play Jan 17 22:26:41 volumio volumio[986]: info: ------------------------------ 2ms Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand play took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: info: Jan 17 22:26:41 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:41 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:41 volumio volumio[986]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jan 17 22:26:41 volumio volumio[986]: info: FusionDsp - ---- read samplerate from file: 44100 Jan 17 22:26:41 volumio volumio[986]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jan 17 22:26:41 volumio volumio[986]: info: Jan 17 22:26:41 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand status took 17 milliseconds Jan 17 22:26:41 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand status took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:41 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"world-etc-flacm","artist":null,"album":null,"uri":"http://stream.radioparadise.com/world-etc-flacm","trackType":""} Jan 17 22:26:41 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus stop Jan 17 22:26:41 volumio volumio[986]: info: ------------------------------ 19ms Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:41 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"world-etc-flacm","artist":null,"album":null,"uri":"http://stream.radioparadise.com/world-etc-flacm","trackType":""} Jan 17 22:26:41 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus play Jan 17 22:26:41 volumio volumio[986]: info: Received an update from plugin. extracting info from payload Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:41 volumio volumio[986]: info: ------------------------------ 10ms Jan 17 22:26:41 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:41 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:41 volumio volumio[986]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jan 17 22:26:41 volumio volumio[986]: info: Jan 17 22:26:41 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:41 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:41 volumio volumio[986]: info: Jan 17 22:26:41 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:41 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:41 volumio volumio[986]: info: ------------------------------ 1ms Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand status took 1 milliseconds Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:41 volumio volumio[986]: info: sendMpdCommand playlistinfo took 0 milliseconds Jan 17 22:26:41 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:41 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"world-etc-flacm","artist":"Radio Paradise World-Etc Mix (flac) - playlist: radioparadise.com","album":null,"uri":"http://stream.radioparadise.com/world-etc-flacm","trackType":""} Jan 17 22:26:41 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus play Jan 17 22:26:41 volumio volumio[986]: info: Received an update from plugin. extracting info from payload Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:41 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:41 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:41 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:41 volumio volumio[986]: info: ------------------------------ 8ms Jan 17 22:26:41 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:41 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:42 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:42 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:42 volumio wpa_supplicant[881]: RRM: Ignoring radio measurement request: Not RRM network Jan 17 22:26:43 volumio volumio[986]: info: Jan 17 22:26:43 volumio volumio[986]: ---------------------------- MPD announces system playlist update Jan 17 22:26:43 volumio volumio[986]: info: Ignoring MPD Status Update Jan 17 22:26:43 volumio volumio[986]: info: Jan 17 22:26:43 volumio volumio[986]: ---------------------------- MPD announces state update: player Jan 17 22:26:43 volumio volumio[986]: info: ControllerMpd::getState Jan 17 22:26:43 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand status Jan 17 22:26:43 volumio volumio[986]: info: ------------------------------ 2ms Jan 17 22:26:43 volumio volumio[986]: info: sendMpdCommand status took 2 milliseconds Jan 17 22:26:43 volumio volumio[986]: verbose: ControllerMpd::parseState Jan 17 22:26:43 volumio volumio[986]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 17 22:26:43 volumio volumio[986]: info: sendMpdCommand playlistinfo took 1 milliseconds Jan 17 22:26:43 volumio volumio[986]: verbose: ControllerMpd::parseTrackInfo Jan 17 22:26:43 volumio volumio[986]: info: ControllerMpd::pushState Jan 17 22:26:43 volumio volumio[986]: info: CoreCommandRouter::servicePushState Jan 17 22:26:43 volumio volumio[986]: info: CorePlayQueue::getTrack 0 Jan 17 22:26:43 volumio volumio[986]: verbose: STATE SERVICE {"status":"play","position":0,"seek":3088,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Santi & Tuğçe - Se va, se va","artist":"Radio Paradise World-Etc Mix (flac) - playlist: radioparadise.com","album":null,"uri":"http://stream.radioparadise.com/world-etc-flacm","trackType":""} Jan 17 22:26:43 volumio volumio[986]: verbose: CURRENT POSITION 0 Jan 17 22:26:43 volumio volumio[986]: info: CoreStateMachine::syncState stateService play Jan 17 22:26:43 volumio volumio[986]: info: CoreStateMachine::syncState currentStatus play Jan 17 22:26:43 volumio volumio[986]: info: Received an update from plugin. extracting info from payload Jan 17 22:26:43 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jan 17 22:26:43 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:43 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 17 22:26:43 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:43 volumio volumio[986]: info: CoreStateMachine::pushState Jan 17 22:26:43 volumio volumio[986]: info: CoreCommandRouter::volumioPushState Jan 17 22:26:43 volumio volumio[986]: info: ------------------------------ 11ms Jan 17 22:26:43 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:43 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:44 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:44 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 704. Jan 17 22:26:44 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:44 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:44 volumio go-librespot[16360]: Librespot-go daemon starting... Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=info msg="generated new device id: 4931295adbecbc17532a5c7d985af114ad1d4fda" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=debug msg="zeroconf server listening on port 43463" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=debug msg="obtained new client token: AACM8XHaqakjMtvetRbR3XJVFcwe14fHuHA5/gRih0I6DPcUp0H49ncWC6ZNrS3xDvH1xufaxHl+yC8pehrK46V9ePB+fLJ5fMWbK+/OuA/UfSJ5rKJxu5iJcx9lUiF5XuaQ+6FIrgt3ip7Wqz4ZdtwodbGfnq3EXOve06gBKhnudfqmriLCSMbW0PsxmlLb4ax7KnJQvlArWaM4Op3gAV/EqhUT53GLK8TQSBSbS/9WUjzjVS69/75lHgXj8kY=" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:44 volumio go-librespot[16360]: time="2025-01-17T22:26:44+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:45 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:45 volumio go-librespot[16360]: time="2025-01-17T22:26:45+01:00" level=debug msg="new websocket client" Jan 17 22:26:45 volumio volumio[986]: info: Connection to go-librespot Websocket established Jan 17 22:26:45 volumio go-librespot[16360]: time="2025-01-17T22:26:45+01:00" level=debug msg="completed challenge" Jan 17 22:26:45 volumio go-librespot[16360]: time="2025-01-17T22:26:45+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:45 volumio volumio[986]: info: Connection to go-librespot Websocket closed Jan 17 22:26:48 volumio volumio[986]: info: Getting Spotify volume Jan 17 22:26:48 volumio volumio[986]: (node:986) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:48 volumio volumio[986]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jan 17 22:26:48 volumio volumio[986]: (node:986) 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: 188) Jan 17 22:26:48 volumio volumio[986]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jan 17 22:26:48 volumio volumio[986]: info: CoreCommandRouter::volumioGetState Jan 17 22:26:48 volumio volumio[986]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40 Jan 17 22:26:48 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:48 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 705. Jan 17 22:26:48 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:48 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:48 volumio go-librespot[16382]: Librespot-go daemon starting... Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=info msg="generated new device id: f6c764a7adb372b1db704bbfdbfbcbb89eac0d05" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=debug msg="zeroconf server listening on port 45121" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=debug msg="obtained new client token: AADX/ZLBRB3u3jVBDI3OPrDpDyER0E31FfmhXa4O4tbSRWjtad+NVOyYDtIqAq7AsHuONzaBpv4bSyFHBEz7E3kHcHGPKAC1Qn5lyY4dDAbdc2/rp9hUns60TcgZqFp5IxKB8GVQzkdpSFqaA5FcrFEGZusBv2384msgzINcf6Vn5ghO+l+F9myDJ9EpUI8kEzqJR29f/CcmJyhBCy4HY+W/jfkn81zHQmURNGIMdYE+cNM3+Jr09Hd6A8cZQEI=" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:48 volumio go-librespot[16382]: time="2025-01-17T22:26:48+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:49 volumio go-librespot[16382]: time="2025-01-17T22:26:49+01:00" level=debug msg="completed challenge" Jan 17 22:26:49 volumio go-librespot[16382]: time="2025-01-17T22:26:49+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:51 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:51 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:52 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 706. Jan 17 22:26:52 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:52 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:52 volumio go-librespot[16434]: Librespot-go daemon starting... Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=info msg="generated new device id: f351c2a7ec2215348ca211e1af340afeb8715287" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=debug msg="zeroconf server listening on port 37117" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=debug msg="obtained new client token: AACzPdiHofceqXSFboVVC8HZSldJCc5bUGDaSr6tzCRdVJTBnJzmBGhITwOZ+hz/+kKEBXGQUv90yEoVf2UEblQSBpbFHufOYkIqhHRoxOrqTemN4XMqX2fxOKjblvxy4cC05kJGe9YL+28PoSQnKTHny/hhgc92bAp/4TzTYBlfX+sLBdjquRA3orJNDy7yyU2eehbTZAEF90/7UbABKGR1SiWvi8gkQjPvHvbbirxxfs+udD/ACMzz5X4kFxU=" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:52 volumio go-librespot[16434]: time="2025-01-17T22:26:52+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:53 volumio go-librespot[16434]: time="2025-01-17T22:26:53+01:00" level=debug msg="completed challenge" Jan 17 22:26:53 volumio go-librespot[16434]: time="2025-01-17T22:26:53+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:54 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:54 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:26:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:26:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 707. Jan 17 22:26:56 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:26:56 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:26:56 volumio go-librespot[16456]: Librespot-go daemon starting... Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=info msg="generated new device id: adccb658d9d47de3e27d51070e3a5aeec43a9a87" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=debug msg="zeroconf server listening on port 43261" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=debug msg="obtained new client token: AACzdRhvDc3nGJ6231dL/JXAz3bgr4lAJHCT3CZB6weK+oUumywfKZ3WmNNNFOg7XKUda8vlEpoecIE6L7O5PaE5g1ucCpRuFKbrJvRkVHrH9Slpvz/ySHKZEA4+V+nP67TGU/l+sZjEVmrjWWukWx9Yw1fGYafn4hxOltFzRL1u/8itAUz1DlrpEx58zpkQ4ILwGCIgEEQPKC0lic++IOdxz+hJK2f8BI0+XkwqNMIrRbxUcmh0ALAowKOChe0=" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:26:56 volumio go-librespot[16456]: time="2025-01-17T22:26:56+01:00" level=debug msg="completed keyexchange" Jan 17 22:26:57 volumio go-librespot[16456]: time="2025-01-17T22:26:57+01:00" level=debug msg="completed challenge" Jan 17 22:26:57 volumio go-librespot[16456]: time="2025-01-17T22:26:57+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:26:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:26:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:26:57 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:26:57 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:27:00 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jan 17 22:27:00 volumio volumio[986]: info: Preload queue cleared Jan 17 22:27:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:27:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 708. Jan 17 22:27:00 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:27:00 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:27:00 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:27:00 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:27:00 volumio go-librespot[16468]: Librespot-go daemon starting... Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=info msg="generated new device id: 6b2b809f07b1db2aae59b2b0e62aea4c9a1e7cae" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=debug msg="zeroconf server listening on port 45653" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=debug msg="obtained new client token: AAAKjQu0Z0TTfEaLdJEWMRmuV5oJlsEwk8ZIwmvSltwwQOfU7rZlfySFUBhxN9U245VPn+Sx0V7bbZVcG5DxkYWirdegQtChgAQT9BrQNkbko+hHyleJAmtkD3oh2UJsPZvU+I2tQTMFJDRSH5KsU7f2+ayd7IqkZa8D0g6OVQTJvf+z1QKbyDWHh8wl9oB3twT1KzRnctdWhz0jZkGPf7TGj3352mBj2bWKFh9WTRiSlcWA/KxE9Sy4unL6evw=" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:27:00 volumio go-librespot[16468]: time="2025-01-17T22:27:00+01:00" level=debug msg="completed keyexchange" Jan 17 22:27:01 volumio go-librespot[16468]: time="2025-01-17T22:27:01+01:00" level=debug msg="completed challenge" Jan 17 22:27:01 volumio go-librespot[16468]: time="2025-01-17T22:27:01+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:27:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:27:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:27:02 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jan 17 22:27:02 volumio volumio[986]: info: Preload queue cleared Jan 17 22:27:03 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:27:03 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:27:04 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jan 17 22:27:04 volumio volumio[986]: info: Preload queue cleared Jan 17 22:27:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:27:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 709. Jan 17 22:27:04 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:27:04 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:27:04 volumio go-librespot[16477]: Librespot-go daemon starting... Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=info msg="generated new device id: 6c7b951fb45be76cc325d04b415db786936ab2b2" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=debug msg="zeroconf server listening on port 40553" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=debug msg="obtained new client token: AABI0QmE6dUUlTeOqBif30PxwrY+lz3UOrsK7HFVx93wIY9pZ2iPQbk1ABW4CWY3bShl7hnzaY0nE47K3iE6dHuDi1eWYQTzJF7rv4VhxY6o9lYqYlIdNF5jP9EBOZRdXBOVDk68eSPuDNuTvdVdsc5z2elfaQFqfJ3lx6/3MEyJrnaJsHojVygaeeaBw5U2z2BKAS53O36lrPx5vBgAsyG8cucvXFRVSraat+duhJj9Ds3FRX7ulUV0ThiW+XQ=" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:27:04 volumio go-librespot[16477]: time="2025-01-17T22:27:04+01:00" level=debug msg="completed keyexchange" Jan 17 22:27:05 volumio go-librespot[16477]: time="2025-01-17T22:27:05+01:00" level=debug msg="completed challenge" Jan 17 22:27:05 volumio go-librespot[16477]: time="2025-01-17T22:27:05+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:27:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:27:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:27:06 volumio volumio[986]: info: Initializing connection to go-librespot Websocket Jan 17 22:27:06 volumio volumio[986]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jan 17 22:27:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jan 17 22:27:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 710. Jan 17 22:27:08 volumio systemd[1]: Stopped go-librespot Daemon. Jan 17 22:27:08 volumio systemd[1]: Started go-librespot Daemon. Jan 17 22:27:08 volumio go-librespot[16501]: Librespot-go daemon starting... Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=info msg="generated new device id: 021f16583ef06ab1903b0735aa17e8091fbfd44e" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=debug msg="stored credentials found for noworo" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=debug msg="zeroconf server listening on port 34125" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=debug msg="obtained new client token: AAD+RuCsz8lUrapgNCELKn3JKvYLL27CgzoDj3W9t1aio3S5gseC9JkRzyFdSNd32TUOS2HtsFesU0PCOUXJ+T0H1ri8XsWUOkq98B0chZwupvgpe4vASVSMxsXkaqccixlT/Vcs5dj6qc2PyTQwWy6NZ+PpflnJtLf0dHlQD05Puc8EN9brBn1mPiDxITGPoAk5b74xCdaFuKSFH9miTBhE9sQ+yyyyZbxlnTsKapnsk4S0MXkFEtYCjDEtFSA=" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=info msg="connected to ap-gew4.spotify.com:4070" Jan 17 22:27:08 volumio go-librespot[16501]: time="2025-01-17T22:27:08+01:00" level=debug msg="completed keyexchange" Jan 17 22:27:09 volumio volumio[986]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jan 17 22:27:09 volumio volumio[986]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 17 22:27:09 volumio volumio[986]: TypeError: Cannot read property 'length' of undefined Jan 17 22:27:09 volumio volumio[986]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jan 17 22:27:09 volumio volumio[986]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jan 17 22:27:09 volumio volumio[986]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jan 17 22:27:09 volumio volumio[986]: at Parser.emit (events.js:315:20) Jan 17 22:27:09 volumio volumio[986]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jan 17 22:27:09 volumio volumio[986]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jan 17 22:27:09 volumio volumio[986]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jan 17 22:27:09 volumio volumio[986]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jan 17 22:27:09 volumio volumio[986]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jan 17 22:27:09 volumio volumio[986]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jan 17 22:27:09 volumio volumio[986]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jan 17 22:27:09 volumio volumio[986]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jan 17 22:27:09 volumio volumio[986]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jan 17 22:27:09 volumio volumio[986]: at IncomingMessage.emit (events.js:327:22) Jan 17 22:27:09 volumio volumio[986]: at endReadableNT (internal/streams/readable.js:1327:12) Jan 17 22:27:09 volumio volumio[986]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jan 17 22:27:09 volumio volumio[986]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 17 22:27:09 volumio go-librespot[16501]: time="2025-01-17T22:27:09+01:00" level=debug msg="completed challenge" Jan 17 22:27:09 volumio go-librespot[16501]: time="2025-01-17T22:27:09+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jan 17 22:27:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jan 17 22:27:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jan 17 22:27:09 volumio sudo[16518]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-01-17 22:26 Jan 17 22:27:09 volumio sudo[16518]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="cc0042a1eab1cb7982711a1347e242f8947b54b6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="d316d397153fbb98c246d670c12f98a120b995a2" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 11 Jan 2025 10:58:50 AM CET" VOLUMIO_VERSION="3.788" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="e6f1869148b01453dc48d3e2d79d1421"