-- Logs begin at Wed 2025-07-02 21:29:25 +07, end at Wed 2025-07-02 21:33:39 +07. -- Jul 02 21:32:01 volumio2 volumio[1029]: info: Getting Spotify volume Jul 02 21:32:01 volumio2 volumio[1029]: (node:1029) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:01 volumio2 volumio[1029]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 02 21:32:01 volumio2 volumio[1029]: (node:1029) 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: 11) Jul 02 21:32:01 volumio2 volumio[1029]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 02 21:32:01 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:32:01 volumio2 volumio[1029]: info: CorePlayQueue::getTrack 0 Jul 02 21:32:01 volumio2 volumio[1029]: info: Clearing queue after UPNP request Jul 02 21:32:02 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:02 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:02 volumio2 volumio[1029]: info: CoreStateMachine::ClearQueue Jul 02 21:32:02 volumio2 volumio[1029]: info: CoreStateMachine::stop Jul 02 21:32:02 volumio2 volumio[1029]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 02 21:32:02 volumio2 volumio[1029]: info: CorePlayQueue::clearPlayQueue Jul 02 21:32:02 volumio2 volumio[1029]: info: CorePlayQueue::saveQueue Jul 02 21:32:02 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:02 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushQueue Jul 02 21:32:02 volumio2 volumio[1029]: error: Upnp client error: Error: This socket has been ended by the other party Jul 02 21:32:02 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:02 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 34. Jul 02 21:32:02 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:02 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:02 volumio2 go-librespot[2604]: Librespot-go daemon starting... Jul 02 21:32:02 volumio2 go-librespot[2604]: time="2025-07-02T21:32:02+07:00" level=info msg="generated new device id: e667aae862eb97345c994ce1af54cb967c966bce" Jul 02 21:32:02 volumio2 go-librespot[2604]: time="2025-07-02T21:32:02+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:02 volumio2 go-librespot[2604]: time="2025-07-02T21:32:02+07:00" level=debug msg="obtained new client token: AABP8lgWNgphA/el5pNR8/+OPEoRE3b/ikrAS2lk2wQPVVIZlB9Mn1ntAE/dx4MY0edTxUgfC0aNb8QfAH6dGO6vpWgZtARXKssSBn9WT13uqXCQNjLn5PoOA1zZbAuAI9M3JkbyOO81vEKgCFHWMJtTllzb7R29jGmK6N3KXp2zxBKuJ1jGIXMnPm1jEf43z0eKcbxDbrYgLtNLKl631DgHSZf3TQzRarEoMQ+/YdkLo32e+gUphT6tzY8E" Jul 02 21:32:02 volumio2 go-librespot[2604]: time="2025-07-02T21:32:02+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:32:02 volumio2 go-librespot[2604]: time="2025-07-02T21:32:02+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:03 volumio2 go-librespot[2604]: time="2025-07-02T21:32:03+07:00" level=debug msg="completed challenge" Jul 02 21:32:03 volumio2 go-librespot[2604]: time="2025-07-02T21:32:03+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:03 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:03 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:03 volumio2 volumio[1029]: info: Starting UPNP Playback Jul 02 21:32:03 volumio2 volumio[1029]: info: Preparing playback through UPNP Jul 02 21:32:03 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:32:03 volumio2 volumio[1029]: info: CorePlayQueue::getTrack 0 Jul 02 21:32:03 volumio2 volumio[1029]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 02 21:32:04 volumio2 volumio[1029]: info: Jul 02 21:32:04 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:04 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:04 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:32:04 volumio2 volumio[1029]: info: Jul 02 21:32:04 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:04 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:04 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:32:04 volumio2 volumio[1029]: info: Jul 02 21:32:04 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:04 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:04 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:32:04 volumio2 volumio[1029]: info: Jul 02 21:32:04 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:04 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:04 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:32:04 volumio2 volumio[1029]: info: Jul 02 21:32:04 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:04 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:04 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:32:04 volumio2 volumio[1029]: info: Jul 02 21:32:04 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:04 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:04 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:32:05 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:05 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:05 volumio2 volumio[1029]: info: Jul 02 21:32:05 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:32:05 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:32:05 volumio2 volumio[1029]: info: Jul 02 21:32:05 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:32:05 volumio2 volumio[1029]: info: sendMpdCommand status took 1 milliseconds Jul 02 21:32:05 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:32:05 volumio2 volumio[1029]: info: sendMpdCommand status took 1 milliseconds Jul 02 21:32:05 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 1 milliseconds Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:32:05 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:32:05 volumio2 volumio[1029]: verbose: In UPNP mode Jul 02 21:32:05 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":240,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Kiss","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515633.flac","trackType":"qobuz"} Jul 02 21:32:05 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService play Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus stop Jul 02 21:32:05 volumio2 volumio[1029]: info: ------------------------------ 9ms Jul 02 21:32:05 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 4 milliseconds Jul 02 21:32:05 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:32:05 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:32:05 volumio2 volumio[1029]: verbose: In UPNP mode Jul 02 21:32:05 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":240,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Kiss","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515633.flac","trackType":"qobuz"} Jul 02 21:32:05 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService play Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus play Jul 02 21:32:05 volumio2 volumio[1029]: info: Received an update from plugin. extracting info from payload Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:05 volumio2 volumio[1029]: info: ------------------------------ 18ms Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:32:05 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:32:05 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:32:05 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:32:06 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:06 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Jul 02 21:32:06 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:06 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:06 volumio2 go-librespot[2627]: Librespot-go daemon starting... Jul 02 21:32:06 volumio2 go-librespot[2627]: time="2025-07-02T21:32:06+07:00" level=info msg="generated new device id: 318fdd7b7682af9ed560fa6a0b2e416a07021195" Jul 02 21:32:06 volumio2 go-librespot[2627]: time="2025-07-02T21:32:06+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:06 volumio2 go-librespot[2627]: time="2025-07-02T21:32:06+07:00" level=debug msg="obtained new client token: AAA3aeEgK1/uQ1ADGzEOtDnfbM9AzSEqTpbiacKE7D6dEFcMoX86ozG9oxgkAB7p6jV/yXWNUxoUJXgQnkaVcMeFxwGIl6AuFjtmB8sBtuS/deK7zbb/gddac1f3Dg7mBnWV8fBFY1JPdDA9hVuXTO6wQHhpQALLbB7L2mxVZlAprhk2PcgeaBcvbhl4LLw3mvfphMT0lD1C6w9YZt9vY7OBuLtwLC3DoIkvV/aB507MP/4hJSXLOOJMFz7A" Jul 02 21:32:06 volumio2 go-librespot[2627]: time="2025-07-02T21:32:06+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:07 volumio2 go-librespot[2627]: time="2025-07-02T21:32:07+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:07 volumio2 go-librespot[2627]: time="2025-07-02T21:32:07+07:00" level=debug msg="completed challenge" Jul 02 21:32:07 volumio2 go-librespot[2627]: time="2025-07-02T21:32:07+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:07 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:07 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:08 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:08 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:10 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:10 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Jul 02 21:32:10 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:10 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:10 volumio2 go-librespot[2661]: Librespot-go daemon starting... Jul 02 21:32:10 volumio2 go-librespot[2661]: time="2025-07-02T21:32:10+07:00" level=info msg="generated new device id: f9379a5bde78be99427793f2f7592859e581d3fa" Jul 02 21:32:10 volumio2 go-librespot[2661]: time="2025-07-02T21:32:10+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:11 volumio2 go-librespot[2661]: time="2025-07-02T21:32:11+07:00" level=debug msg="obtained new client token: AAAPaWzqMUorki5ZSjHSKqiDrCxMG+GBenhJNSAbxL0hkwxVoyGS5i998C+1fbvfAzmQe263A/q5uNprrhCh0S29FxRmv1M3F+boucU3T52xtDLZ1A/+WFYYZwRgfyjCEUzeh4NX77D+WEeMyVR8tT2KxW292MxLyQufbgWkAYV6e4cjaFLVIOSs6Ech8/kezaBiAtH+0Q0xh87hP5xAEec3rWU5oFmKQmQ+iL07dZtgkVSNwRTep8PZwQ==" Jul 02 21:32:11 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:11 volumio2 volumio[1029]: info: Connection to go-librespot Websocket established Jul 02 21:32:11 volumio2 go-librespot[2661]: time="2025-07-02T21:32:11+07:00" level=debug msg="new websocket client" Jul 02 21:32:11 volumio2 go-librespot[2661]: time="2025-07-02T21:32:11+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:11 volumio2 go-librespot[2661]: time="2025-07-02T21:32:11+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:11 volumio2 go-librespot[2661]: time="2025-07-02T21:32:11+07:00" level=debug msg="completed challenge" Jul 02 21:32:11 volumio2 go-librespot[2661]: time="2025-07-02T21:32:11+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:11 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:11 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:11 volumio2 volumio[1029]: info: Connection to go-librespot Websocket closed Jul 02 21:32:14 volumio2 volumio[1029]: info: Getting Spotify volume Jul 02 21:32:14 volumio2 volumio[1029]: (node:1029) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:14 volumio2 volumio[1029]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 02 21:32:14 volumio2 volumio[1029]: (node:1029) 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: 12) Jul 02 21:32:14 volumio2 volumio[1029]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 02 21:32:14 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:32:14 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:14 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:15 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:15 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37. Jul 02 21:32:15 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:15 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:15 volumio2 go-librespot[2678]: Librespot-go daemon starting... Jul 02 21:32:15 volumio2 go-librespot[2678]: time="2025-07-02T21:32:15+07:00" level=info msg="generated new device id: 4db4b453d22055bfcd3be1f1e5786cfd5db74a83" Jul 02 21:32:15 volumio2 go-librespot[2678]: time="2025-07-02T21:32:15+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:15 volumio2 go-librespot[2678]: time="2025-07-02T21:32:15+07:00" level=debug msg="obtained new client token: AAAaJ+L57MPuiMkV5SD/mra7drwEl1zd0tq9zlOjL3ffzScRSZazU/5IdUsnt8AsWJ2rN7vazrB0VS3khYedBjhQfd+iOVgJA5pkOBsjg8W+0UgidjLbgUTqNRZNZZheTUAajI11N52xjqFkdNksZq/dETr0o8GVfSDYV4kWuyEqwyqn6amX2vZDK1y6b+eVV3hupE2NiruUTSMdw0T35NRwXuvAo6WHQcWk3zawqWnyDQ2lILfYR2yixw==" Jul 02 21:32:15 volumio2 go-librespot[2678]: time="2025-07-02T21:32:15+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:32:15 volumio2 go-librespot[2678]: time="2025-07-02T21:32:15+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:15 volumio2 go-librespot[2678]: time="2025-07-02T21:32:15+07:00" level=debug msg="completed challenge" Jul 02 21:32:16 volumio2 go-librespot[2678]: time="2025-07-02T21:32:16+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:16 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:16 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:17 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:17 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:19 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:19 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38. Jul 02 21:32:19 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:19 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:19 volumio2 go-librespot[2708]: Librespot-go daemon starting... Jul 02 21:32:19 volumio2 go-librespot[2708]: time="2025-07-02T21:32:19+07:00" level=info msg="generated new device id: a754c0286bda3ddd91f32bbb312a088a4dfc2262" Jul 02 21:32:19 volumio2 go-librespot[2708]: time="2025-07-02T21:32:19+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:19 volumio2 go-librespot[2708]: time="2025-07-02T21:32:19+07:00" level=debug msg="obtained new client token: AACp7MTOWbU54cq1sCrgCYd0VPIKzwWX+fvbAvmKkuBZWVFJJzJmlipc1Pj4hpKeyZ/Wp2nsmC0FUVLtEUKQqbSpUNB3FZUkEQ3eXfS8y2CqefWhSveEhG45lYM2sCGib1MWvZL1RpdWBAlqOcTeioNJWUG28S7DQot/bTiIAxbAF+FpNkz+Gp0PZpT0/p4g8Neh9UbBY4ZQrgN11SSBbbUMxB29FjGt7zMRf3vBkZeq5DUV3Cs/u0D9IA==" Jul 02 21:32:19 volumio2 go-librespot[2708]: time="2025-07-02T21:32:19+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:32:19 volumio2 go-librespot[2708]: time="2025-07-02T21:32:19+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:20 volumio2 go-librespot[2708]: time="2025-07-02T21:32:20+07:00" level=debug msg="completed challenge" Jul 02 21:32:20 volumio2 go-librespot[2708]: time="2025-07-02T21:32:20+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:20 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:20 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:20 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:20 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:22 volumio2 volumio[1029]: info: Jul 02 21:32:22 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:32:22 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:32:22 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:32:22 volumio2 volumio[1029]: info: sendMpdCommand status took 1 milliseconds Jul 02 21:32:22 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:32:22 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:32:22 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 1 milliseconds Jul 02 21:32:22 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:32:22 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:22 volumio2 volumio[1029]: info: CorePlayQueue::getTrack 0 Jul 02 21:32:22 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Kiss","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515633.flac","trackType":"qobuz"} Jul 02 21:32:22 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService stop Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus play Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreStateMachine::stPlaybackTimer Jul 02 21:32:22 volumio2 volumio[1029]: info: ------------------------------ 12ms Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:32:22 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:32:22 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:32:23 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:23 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39. Jul 02 21:32:23 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:23 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:23 volumio2 go-librespot[2723]: Librespot-go daemon starting... Jul 02 21:32:23 volumio2 go-librespot[2723]: time="2025-07-02T21:32:23+07:00" level=info msg="generated new device id: 11241da21c6f7b61caff00eb6ca835feefb8271b" Jul 02 21:32:23 volumio2 go-librespot[2723]: time="2025-07-02T21:32:23+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:23 volumio2 go-librespot[2723]: time="2025-07-02T21:32:23+07:00" level=debug msg="obtained new client token: AACBIJ84Jfr/SlU/pj1oe8G358LyMGfckWcwUSWyEpTE5iZu/4JumCESPPbHnPEq0Ae46nG1jiQL8Z1hQJkj9e55ik6wVgN5+YWNjTTkn8ym8MRDkcjQ5nTewBMChWPvuck8e/xUBnraWC96sLsg5n9ZLeJsiRdERZxXXg1a/zv3jtlu4KaJ0RzbaRhrSkD0BZviZTzkYYDnffQ5v5/Ql2broOJUXh3EdgRAYNaYnBqetpzim/vbjMk3Ug==" Jul 02 21:32:23 volumio2 go-librespot[2723]: time="2025-07-02T21:32:23+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:23 volumio2 go-librespot[2723]: time="2025-07-02T21:32:23+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:23 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:23 volumio2 go-librespot[2723]: time="2025-07-02T21:32:23+07:00" level=debug msg="new websocket client" Jul 02 21:32:23 volumio2 volumio[1029]: info: Connection to go-librespot Websocket established Jul 02 21:32:24 volumio2 go-librespot[2723]: time="2025-07-02T21:32:24+07:00" level=debug msg="completed challenge" Jul 02 21:32:24 volumio2 go-librespot[2723]: time="2025-07-02T21:32:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:24 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:24 volumio2 volumio[1029]: info: Connection to go-librespot Websocket closed Jul 02 21:32:24 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:25 volumio2 volumio[1029]: info: Clearing queue after UPNP request Jul 02 21:32:25 volumio2 volumio[1029]: info: CoreStateMachine::ClearQueue Jul 02 21:32:25 volumio2 volumio[1029]: info: CoreStateMachine::stop Jul 02 21:32:25 volumio2 volumio[1029]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 02 21:32:25 volumio2 volumio[1029]: info: CorePlayQueue::clearPlayQueue Jul 02 21:32:25 volumio2 volumio[1029]: info: CorePlayQueue::saveQueue Jul 02 21:32:25 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:25 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushQueue Jul 02 21:32:25 volumio2 volumio[1029]: info: Jul 02 21:32:25 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:25 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:25 volumio2 volumio[1029]: error: updateQueue error: null Jul 02 21:32:25 volumio2 volumio[1029]: info: ------------------------------ 3ms Jul 02 21:32:25 volumio2 volumio[1029]: info: Starting UPNP Playback Jul 02 21:32:25 volumio2 volumio[1029]: info: Preparing playback through UPNP Jul 02 21:32:25 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:32:25 volumio2 volumio[1029]: info: CorePlayQueue::getTrack 0 Jul 02 21:32:25 volumio2 volumio[1029]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 02 21:32:25 volumio2 volumio[1029]: info: Jul 02 21:32:25 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:25 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:25 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:32:25 volumio2 volumio[1029]: info: Jul 02 21:32:25 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:25 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:25 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:32:25 volumio2 volumio[1029]: info: Jul 02 21:32:25 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:25 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:25 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:32:25 volumio2 volumio[1029]: info: Jul 02 21:32:25 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:25 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:25 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:32:25 volumio2 volumio[1029]: info: Jul 02 21:32:25 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:25 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:25 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:32:25 volumio2 volumio[1029]: info: Jul 02 21:32:25 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:32:25 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:32:25 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:32:26 volumio2 volumio[1029]: info: Jul 02 21:32:26 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:32:26 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:32:26 volumio2 volumio[1029]: info: Jul 02 21:32:26 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:32:26 volumio2 volumio[1029]: info: sendMpdCommand status took 1 milliseconds Jul 02 21:32:26 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:32:26 volumio2 volumio[1029]: info: sendMpdCommand status took 1 milliseconds Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:32:26 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 02 21:32:26 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 1 milliseconds Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:32:26 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:32:26 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:32:26 volumio2 volumio[1029]: verbose: In UPNP mode Jul 02 21:32:26 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":225,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Gee Baby Ain't I Good To You","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515634.flac","trackType":"qobuz"} Jul 02 21:32:26 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService play Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus stop Jul 02 21:32:26 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:32:26 volumio2 volumio[1029]: verbose: In UPNP mode Jul 02 21:32:26 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":225,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Gee Baby Ain't I Good To You","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515634.flac","trackType":"qobuz"} Jul 02 21:32:26 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService play Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus play Jul 02 21:32:26 volumio2 volumio[1029]: info: Received an update from plugin. extracting info from payload Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:26 volumio2 volumio[1029]: info: ------------------------------ 12ms Jul 02 21:32:26 volumio2 volumio[1029]: info: ------------------------------ 15ms Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:32:26 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:32:26 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:32:26 volumio2 volumio[1029]: info: Getting Spotify volume Jul 02 21:32:26 volumio2 volumio[1029]: (node:1029) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:26 volumio2 volumio[1029]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 02 21:32:26 volumio2 volumio[1029]: (node:1029) 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: 13) Jul 02 21:32:26 volumio2 volumio[1029]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 02 21:32:26 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:32:27 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:27 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:27 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:27 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40. Jul 02 21:32:27 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:27 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:27 volumio2 go-librespot[2736]: Librespot-go daemon starting... Jul 02 21:32:27 volumio2 go-librespot[2736]: time="2025-07-02T21:32:27+07:00" level=info msg="generated new device id: 73f000c0f99729cecc8e70508be819648aad30a0" Jul 02 21:32:27 volumio2 go-librespot[2736]: time="2025-07-02T21:32:27+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:27 volumio2 go-librespot[2736]: time="2025-07-02T21:32:27+07:00" level=debug msg="obtained new client token: AAC7xcpk1zNdua2LeAt6uSm2buiD3fZBqpeWnfFO/d6MPERK9FZ/0xacvYdpCBJMN3UVfm+ADrrsLHkhPY2ToBDLqRKfazWHXj8IH1t/kDURd/TByswUakz3zBcI/gOIZACGIurivcEJ/kk6qqcLfGjtZKQsbURl86jth9NowZ/QDduWOMqxaREo5OtSPNOERRgFGd1geihd0YqHOg1vVsd30SKLXfNHOan2nSwVeykOfiiWXfG87FUyx4Ys" Jul 02 21:32:27 volumio2 go-librespot[2736]: time="2025-07-02T21:32:27+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:27 volumio2 go-librespot[2736]: time="2025-07-02T21:32:27+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:28 volumio2 go-librespot[2736]: time="2025-07-02T21:32:28+07:00" level=debug msg="completed challenge" Jul 02 21:32:28 volumio2 go-librespot[2736]: time="2025-07-02T21:32:28+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:28 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:28 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:30 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:30 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:31 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:31 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41. Jul 02 21:32:31 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:31 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:31 volumio2 go-librespot[2815]: Librespot-go daemon starting... Jul 02 21:32:31 volumio2 go-librespot[2815]: time="2025-07-02T21:32:31+07:00" level=info msg="generated new device id: 19e40c8a9755a722d8ab4db4840ae6b9e9143840" Jul 02 21:32:31 volumio2 go-librespot[2815]: time="2025-07-02T21:32:31+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:31 volumio2 go-librespot[2815]: time="2025-07-02T21:32:31+07:00" level=debug msg="obtained new client token: AAD8KBmO9TrATmxHZpBIEiKoSkatZkTXtwqOL7P1JpC1Sb27qxSvVoTT3rSU6pt5ER98JltAt8IDyAwu7xOZvsW4vbMS3XlJlrLR/VX4ULz22Px1RwwQPQrkzUZ2CRytrASFAf2ilghEdEraukQnkrp7khTg9/td2R3ht2USciLip6UtPcD2pn1vPfkbbDS6D8tXsN3Jx6jYGZH1pQHu9jSDYahB8Zw8j3ZZVeWeGSE5mWYEYjzJBO6+tpAP" Jul 02 21:32:31 volumio2 go-librespot[2815]: time="2025-07-02T21:32:31+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:31 volumio2 go-librespot[2815]: time="2025-07-02T21:32:31+07:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.241.202:4070: connect: connection refused" Jul 02 21:32:31 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:31 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:33 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:33 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:35 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:35 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42. Jul 02 21:32:35 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:35 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:35 volumio2 go-librespot[2830]: Librespot-go daemon starting... Jul 02 21:32:35 volumio2 go-librespot[2830]: time="2025-07-02T21:32:35+07:00" level=info msg="generated new device id: a8b2a972b5d7db664f8afe6446d6aa7abfc30889" Jul 02 21:32:35 volumio2 go-librespot[2830]: time="2025-07-02T21:32:35+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:35 volumio2 go-librespot[2830]: time="2025-07-02T21:32:35+07:00" level=debug msg="obtained new client token: AADjSbDQFaU2k4Atf/XP87Ca35NLjERd3lGOAVc8+/9/dqOpaGQ7Sf6cMIsOua2gOjH1RohwwJY5hVMekW7+R3+pVDC8FpOyz6v4AmNMtdVCb+9CwFb6dRcee+57bIEp9WoYzsBiULD0WOpO/3E1tNl4qG5iA9x52Ztqvgs/875alXNYClsJhiS6TwraYH5+4xIegSUyF5CU6AiUaxAiL0ivf6U5scITcgompNbtgKNQIoBMl2Fooj7Gtg==" Jul 02 21:32:35 volumio2 go-librespot[2830]: time="2025-07-02T21:32:35+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:32:35 volumio2 go-librespot[2830]: time="2025-07-02T21:32:35+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:35 volumio2 go-librespot[2830]: time="2025-07-02T21:32:35+07:00" level=debug msg="completed challenge" Jul 02 21:32:36 volumio2 go-librespot[2830]: time="2025-07-02T21:32:36+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:36 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:36 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:36 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:36 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:39 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:39 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:39 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:39 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 43. Jul 02 21:32:39 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:39 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:39 volumio2 go-librespot[2860]: Librespot-go daemon starting... Jul 02 21:32:39 volumio2 go-librespot[2860]: time="2025-07-02T21:32:39+07:00" level=info msg="generated new device id: 63e55a9f668869c78bafe705697d475c00d8131e" Jul 02 21:32:39 volumio2 go-librespot[2860]: time="2025-07-02T21:32:39+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:39 volumio2 go-librespot[2860]: time="2025-07-02T21:32:39+07:00" level=debug msg="obtained new client token: AABmMP3UbY1PgScht7vZL4Rn5Odfyk5bIwJcYj+BYCPDIMyGUWRcSOsfiN8JfoJGFYb0XVPoji7M9oNb6gVIV0f89LZClC9H9ul7mRvMCKis/CqUwCdBSJNfNwlRUsoLv++POuMb/Hl79s1cO3g+y1ve5w3ZUyy80VxQhWz2u2avGa9YrNb8BbrdNHP8GfXz0Ozcibb2aEau5SJ82U2tM8kRkP4vK1t6XOHVWC8q/WVeuSeP87CJB5FLuA==" Jul 02 21:32:39 volumio2 go-librespot[2860]: time="2025-07-02T21:32:39+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:39 volumio2 go-librespot[2860]: time="2025-07-02T21:32:39+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:39 volumio2 go-librespot[2860]: time="2025-07-02T21:32:39+07:00" level=debug msg="completed challenge" Jul 02 21:32:40 volumio2 go-librespot[2860]: time="2025-07-02T21:32:40+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:40 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:40 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:42 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:42 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:43 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:43 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 44. Jul 02 21:32:43 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:43 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:43 volumio2 go-librespot[2875]: Librespot-go daemon starting... Jul 02 21:32:43 volumio2 go-librespot[2875]: time="2025-07-02T21:32:43+07:00" level=info msg="generated new device id: 62b3763cab1ff9f07b4c6d055b1d4508892db9c1" Jul 02 21:32:43 volumio2 go-librespot[2875]: time="2025-07-02T21:32:43+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:43 volumio2 go-librespot[2875]: time="2025-07-02T21:32:43+07:00" level=debug msg="obtained new client token: AAB4TCw2zR+tkogjbjAoZfD5Eqfn1ROQXfvLgS+gShjo7AD/hRLAyBGkZ41JoYczuqMJKJyjyGJetmzGZS1H7gu3HYZF7uv2GBpR3/KtWEvOJhBgi4pYGgcwzScTwZzooWtqfqiB5ufFyEjkieDPi2S5UWUoFeyCukmAxt5oywBBbM7TfbZmu12WmOOSFBBk7sfI+lMFtfU+fi8zVJoVMnHXzwyLuNhdy8tIdeGp12MRc/xyHOaQB1iNag==" Jul 02 21:32:43 volumio2 go-librespot[2875]: time="2025-07-02T21:32:43+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:43 volumio2 go-librespot[2875]: time="2025-07-02T21:32:43+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:43 volumio2 volumio[1029]: info: Jul 02 21:32:43 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:32:43 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:32:43 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:32:43 volumio2 volumio[1029]: info: sendMpdCommand status took 0 milliseconds Jul 02 21:32:43 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:32:43 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:32:43 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 0 milliseconds Jul 02 21:32:43 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:32:43 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:43 volumio2 volumio[1029]: info: CorePlayQueue::getTrack 0 Jul 02 21:32:43 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Gee Baby Ain't I Good To You","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515634.flac","trackType":"qobuz"} Jul 02 21:32:43 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService stop Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus play Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreStateMachine::stPlaybackTimer Jul 02 21:32:43 volumio2 volumio[1029]: info: ------------------------------ 13ms Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:32:43 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:32:43 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:32:44 volumio2 go-librespot[2875]: time="2025-07-02T21:32:44+07:00" level=debug msg="completed challenge" Jul 02 21:32:44 volumio2 go-librespot[2875]: time="2025-07-02T21:32:44+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:44 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:44 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:45 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:45 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:47 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:47 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 45. Jul 02 21:32:47 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:47 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:47 volumio2 go-librespot[2883]: Librespot-go daemon starting... Jul 02 21:32:47 volumio2 go-librespot[2883]: time="2025-07-02T21:32:47+07:00" level=info msg="generated new device id: 48b6fbb3dc4ab9a84a1b0183b42d37abd6ee1af9" Jul 02 21:32:47 volumio2 go-librespot[2883]: time="2025-07-02T21:32:47+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:47 volumio2 go-librespot[2883]: time="2025-07-02T21:32:47+07:00" level=debug msg="obtained new client token: AACZRMPgeyIksvGHT48MYvHszrFt4bZCr38/NyvsxZ7oYlTD/P6aq45ZpfXXf03Gca4CG4nJAYOFgNch5wt5JSeVg5nGG+HTXaqEeukh4b7ST/SW72W1cSmkxIJHkHxyDQ8njDCCGVFc+WoNfpAizVScs08L1claBDZCsr/mXka/VZPgmKCaVJRfqw0xKAnMHKi6PEadQi8NzzL9hmBTzVGDTDIrN2/wEKHo8WuAwN+A3d6GnZcwA+NwVA==" Jul 02 21:32:47 volumio2 go-librespot[2883]: time="2025-07-02T21:32:47+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:47 volumio2 go-librespot[2883]: time="2025-07-02T21:32:47+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:47 volumio2 go-librespot[2883]: time="2025-07-02T21:32:47+07:00" level=debug msg="completed challenge" Jul 02 21:32:48 volumio2 go-librespot[2883]: time="2025-07-02T21:32:48+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:48 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:48 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:48 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:48 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:51 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:51 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:51 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:51 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 46. Jul 02 21:32:51 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:51 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:51 volumio2 go-librespot[2908]: Librespot-go daemon starting... Jul 02 21:32:51 volumio2 go-librespot[2908]: time="2025-07-02T21:32:51+07:00" level=info msg="generated new device id: 273492684f61063c3ad91167a093acf79e466a14" Jul 02 21:32:51 volumio2 go-librespot[2908]: time="2025-07-02T21:32:51+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:51 volumio2 go-librespot[2908]: time="2025-07-02T21:32:51+07:00" level=debug msg="obtained new client token: AAB8pO8v9xSZxJqiGDGm+3XyKkAeGYvy2eObtHWXeXDZbC6TNtjB4C/tz2bxY/3PLy/i/9+DcsFGtCi2MPU7S4o4fAIeKmN2v89ffvIWtKrTfD/pgGoBQbn/N20iNW0SnbyITM2GYLIBVaOjSYYMR14xOWNdDyP1mWCy5idehXD1LM024vuLfGr8DfVQ+dr1QoQ9J0doDburiiNQS5VEetukZpAGp7PssRD9OLXjh8nTZReMxvA3c9trlg==" Jul 02 21:32:51 volumio2 go-librespot[2908]: time="2025-07-02T21:32:51+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:32:51 volumio2 go-librespot[2908]: time="2025-07-02T21:32:51+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:52 volumio2 go-librespot[2908]: time="2025-07-02T21:32:52+07:00" level=debug msg="completed challenge" Jul 02 21:32:52 volumio2 go-librespot[2908]: time="2025-07-02T21:32:52+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:52 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:52 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:54 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:54 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:55 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:55 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 47. Jul 02 21:32:55 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:55 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:55 volumio2 go-librespot[2917]: Librespot-go daemon starting... Jul 02 21:32:55 volumio2 go-librespot[2917]: time="2025-07-02T21:32:55+07:00" level=info msg="generated new device id: 42702afa622c9c9a82a92f00d75d867f88d82f4c" Jul 02 21:32:55 volumio2 go-librespot[2917]: time="2025-07-02T21:32:55+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:55 volumio2 go-librespot[2917]: time="2025-07-02T21:32:55+07:00" level=debug msg="obtained new client token: AACLp5qg4Jk67qIhTKM3EGn3qZW+/J5g0ox3uxTVYESy92qRcb7hvpsnb+J2ekmjJf1g7hGFa3CyGaNhscuIme3oc1/FoiSdZFfxa9BAPfbc3YKHvSvJPPvP49GsicDxezaurAxYjhc335F/BCv4ENppRHmFEioopEQWKklLK4KoPwR1n7ziocSMv0Cqblf2Hb3+EKvlAqkwoQCmXBun7pTLPIAxCHnM0bwBDBSuCF+sCleZi3qwxp7h6w==" Jul 02 21:32:55 volumio2 go-librespot[2917]: time="2025-07-02T21:32:55+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:32:55 volumio2 go-librespot[2917]: time="2025-07-02T21:32:55+07:00" level=debug msg="completed keyexchange" Jul 02 21:32:55 volumio2 go-librespot[2917]: time="2025-07-02T21:32:55+07:00" level=debug msg="completed challenge" Jul 02 21:32:56 volumio2 go-librespot[2917]: time="2025-07-02T21:32:56+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:32:56 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:32:56 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:32:57 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:32:57 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:32:59 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:32:59 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 48. Jul 02 21:32:59 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:32:59 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:32:59 volumio2 go-librespot[2941]: Librespot-go daemon starting... Jul 02 21:32:59 volumio2 go-librespot[2941]: time="2025-07-02T21:32:59+07:00" level=info msg="generated new device id: bacee2596975185142b22b4810f71692aea14fc9" Jul 02 21:32:59 volumio2 go-librespot[2941]: time="2025-07-02T21:32:59+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:32:59 volumio2 go-librespot[2941]: time="2025-07-02T21:32:59+07:00" level=debug msg="obtained new client token: AACJFp4drFVeOF3I4/b7nS1wQN24t3K/b2GG0fYbDlL9VfXzi/frtGIYF7dJ6RKPWayFfMbOLE+/YVvYHXf+h+Z/AN42Dc7PuHyu2kwLcPK2dctQma91zcNXKiCRC8vSqZ5aYgr8pOs709RvKZp2NvS4xWe5VzHPVWyMwd3IZ8CO60f22LnjR/zPXnRz+6ii/Ry6RNR7GbezZmz0sXAsRIAtWwFeR1ZaWNru4MMpN41QVwEgpujcUobs1w==" Jul 02 21:32:59 volumio2 go-librespot[2941]: time="2025-07-02T21:32:59+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:32:59 volumio2 go-librespot[2941]: time="2025-07-02T21:32:59+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:00 volumio2 go-librespot[2941]: time="2025-07-02T21:33:00+07:00" level=debug msg="completed challenge" Jul 02 21:33:00 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:00 volumio2 go-librespot[2941]: time="2025-07-02T21:33:00+07:00" level=debug msg="new websocket client" Jul 02 21:33:00 volumio2 volumio[1029]: info: Connection to go-librespot Websocket established Jul 02 21:33:00 volumio2 go-librespot[2941]: time="2025-07-02T21:33:00+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:00 volumio2 volumio[1029]: info: Connection to go-librespot Websocket closed Jul 02 21:33:00 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:00 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:00 volumio2 volumio[1029]: info: Clearing queue after UPNP request Jul 02 21:33:00 volumio2 volumio[1029]: info: CoreStateMachine::ClearQueue Jul 02 21:33:00 volumio2 volumio[1029]: info: CoreStateMachine::stop Jul 02 21:33:00 volumio2 volumio[1029]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 02 21:33:00 volumio2 volumio[1029]: info: CorePlayQueue::clearPlayQueue Jul 02 21:33:00 volumio2 volumio[1029]: info: CorePlayQueue::saveQueue Jul 02 21:33:00 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:33:00 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushQueue Jul 02 21:33:00 volumio2 volumio[1029]: info: Jul 02 21:33:00 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:33:00 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:33:00 volumio2 volumio[1029]: error: updateQueue error: null Jul 02 21:33:00 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:33:00 volumio2 volumio[1029]: info: Starting UPNP Playback Jul 02 21:33:00 volumio2 volumio[1029]: info: Preparing playback through UPNP Jul 02 21:33:00 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:00 volumio2 volumio[1029]: info: CorePlayQueue::getTrack 0 Jul 02 21:33:00 volumio2 volumio[1029]: info: CoreStateMachine::setConsumeUpdateService mpd Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:33:01 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:33:01 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:33:01 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:33:01 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 0ms Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:33:01 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces system playlist update Jul 02 21:33:01 volumio2 volumio[1029]: info: Ignoring MPD Status Update Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 1ms Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:33:01 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:33:01 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:33:01 volumio2 volumio[1029]: info: Jul 02 21:33:01 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:33:01 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:33:01 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:33:01 volumio2 volumio[1029]: info: sendMpdCommand status took 6 milliseconds Jul 02 21:33:01 volumio2 volumio[1029]: info: sendMpdCommand status took 9 milliseconds Jul 02 21:33:01 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:33:01 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:33:01 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:33:01 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:33:01 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 9 milliseconds Jul 02 21:33:01 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 10 milliseconds Jul 02 21:33:01 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:33:01 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:33:01 volumio2 volumio[1029]: verbose: In UPNP mode Jul 02 21:33:01 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"play","position":0,"seek":842,"duration":240,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"437 Kbps","isStreaming":false,"title":"Kiss","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515633.flac","trackType":"qobuz"} Jul 02 21:33:01 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService play Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus stop Jul 02 21:33:01 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:33:01 volumio2 volumio[1029]: verbose: In UPNP mode Jul 02 21:33:01 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"play","position":0,"seek":842,"duration":240,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"470 Kbps","isStreaming":false,"title":"Kiss","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515633.flac","trackType":"qobuz"} Jul 02 21:33:01 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService play Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus play Jul 02 21:33:01 volumio2 volumio[1029]: info: Received an update from plugin. extracting info from payload Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 63ms Jul 02 21:33:01 volumio2 volumio[1029]: info: ------------------------------ 106ms Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:33:01 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:33:01 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:33:01 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:33:03 volumio2 volumio[1029]: info: Getting Spotify volume Jul 02 21:33:03 volumio2 volumio[1029]: (node:1029) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:03 volumio2 volumio[1029]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 02 21:33:03 volumio2 volumio[1029]: (node:1029) 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: 14) Jul 02 21:33:03 volumio2 volumio[1029]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 02 21:33:03 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:03 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:03 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:03 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:03 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 49. Jul 02 21:33:03 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:03 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:03 volumio2 go-librespot[2961]: Librespot-go daemon starting... Jul 02 21:33:03 volumio2 go-librespot[2961]: time="2025-07-02T21:33:03+07:00" level=info msg="generated new device id: b0d5d0bf2fab0264604fcd75045abd00f0c82a4d" Jul 02 21:33:03 volumio2 go-librespot[2961]: time="2025-07-02T21:33:03+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:03 volumio2 go-librespot[2961]: time="2025-07-02T21:33:03+07:00" level=debug msg="obtained new client token: AAA3qm7PZJyy0FG3ErxQzYTMQieZgnEh48cVIgRUSqs+1tm0lYWcWIQG7ErtkmSfLbZVMfR0PoEc2iM5lPaqWr8k5q3+0yhkbglyIn+IWEvzxETtGVpu+pmCI3iSnzBuH9MsfMHypchr63vGcxM1K9EFk7GyXSamCPFWQ/5aD7bTOfO3BGbDxlVICMXpMReSXQ+BZnN3W//fVAZ1Qxf3RcOU/RMyf40fSJ5qD5dI67PGjvOsxsleesbftdU9" Jul 02 21:33:03 volumio2 go-librespot[2961]: time="2025-07-02T21:33:03+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:33:03 volumio2 go-librespot[2961]: time="2025-07-02T21:33:03+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:04 volumio2 go-librespot[2961]: time="2025-07-02T21:33:04+07:00" level=debug msg="completed challenge" Jul 02 21:33:04 volumio2 go-librespot[2961]: time="2025-07-02T21:33:04+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:04 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:04 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:06 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:06 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:07 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:07 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 50. Jul 02 21:33:07 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:07 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:07 volumio2 go-librespot[2986]: Librespot-go daemon starting... Jul 02 21:33:07 volumio2 go-librespot[2986]: time="2025-07-02T21:33:07+07:00" level=info msg="generated new device id: 1420d62156487a6e46192f0436493393002d94f6" Jul 02 21:33:07 volumio2 go-librespot[2986]: time="2025-07-02T21:33:07+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:07 volumio2 go-librespot[2986]: time="2025-07-02T21:33:07+07:00" level=debug msg="obtained new client token: AACTSXqo2VCpHjHMGfRE5wgYhGVQzi2Jx+vbG1X2XXWX+4SGi2gnM15V38uanbE8bXpw9qlCIBiw9t8N1Kjkky4UBzipqPQxkX9EZYcvuSgmOPRI/HSiNRpvELEj0MJcrnzoPtmDaXB8jLpP11PZ7zircDJnf3fe0Y2X3P2jyFReCreUbmMeyu9Up8MzB4io2cLqVRKeTvxCsAgZ7Xs9Nn3uHsseP9y+nv+AChXb4/6UHtFYxxolXc0rcY87" Jul 02 21:33:07 volumio2 go-librespot[2986]: time="2025-07-02T21:33:07+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:33:08 volumio2 go-librespot[2986]: time="2025-07-02T21:33:08+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:08 volumio2 go-librespot[2986]: time="2025-07-02T21:33:08+07:00" level=debug msg="completed challenge" Jul 02 21:33:08 volumio2 go-librespot[2986]: time="2025-07-02T21:33:08+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:08 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:08 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:09 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:09 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:11 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:11 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 51. Jul 02 21:33:11 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:11 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:11 volumio2 go-librespot[3000]: Librespot-go daemon starting... Jul 02 21:33:11 volumio2 go-librespot[3000]: time="2025-07-02T21:33:11+07:00" level=info msg="generated new device id: 94ffae9a9cc000375d2b49c2925ed38359d06720" Jul 02 21:33:11 volumio2 go-librespot[3000]: time="2025-07-02T21:33:11+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:11 volumio2 go-librespot[3000]: time="2025-07-02T21:33:11+07:00" level=debug msg="obtained new client token: AADmrpuWSjI0RRSnmOS52nXcSnFUAc//2+3mC0T5gacd4i1vOtCFjgtSEXgfMcmSefwQ4tb9vF0bcfzAhf7PlxK5h0kHtetoY4iDl1fN3XWS4AZ+Eb903V0mXcyB6SdxuK2w8HbbM4IBtOZmimXVLdHlPMogCxzLK9R8APb58yLV+HrcDxWgwv3kfDzlam4eQnVXoJgvZ1/wx5SdmUu+QyjE54+7stTKZ99gjAled9ZH3gSSEy94DoXlu/MZ" Jul 02 21:33:11 volumio2 go-librespot[3000]: time="2025-07-02T21:33:11+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:33:12 volumio2 go-librespot[3000]: time="2025-07-02T21:33:12+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:12 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:12 volumio2 go-librespot[3000]: time="2025-07-02T21:33:12+07:00" level=debug msg="new websocket client" Jul 02 21:33:12 volumio2 volumio[1029]: info: Connection to go-librespot Websocket established Jul 02 21:33:12 volumio2 go-librespot[3000]: time="2025-07-02T21:33:12+07:00" level=debug msg="completed challenge" Jul 02 21:33:12 volumio2 go-librespot[3000]: time="2025-07-02T21:33:12+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:12 volumio2 volumio[1029]: info: Connection to go-librespot Websocket closed Jul 02 21:33:12 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:12 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:13 volumio2 volumio[1029]: info: Jul 02 21:33:13 volumio2 volumio[1029]: ---------------------------- MPD announces state update: player Jul 02 21:33:13 volumio2 volumio[1029]: info: ControllerMpd::getState Jul 02 21:33:13 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand status Jul 02 21:33:13 volumio2 volumio[1029]: info: sendMpdCommand status took 1 milliseconds Jul 02 21:33:13 volumio2 volumio[1029]: verbose: ControllerMpd::parseState Jul 02 21:33:13 volumio2 volumio[1029]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 02 21:33:13 volumio2 volumio[1029]: info: sendMpdCommand playlistinfo took 1 milliseconds Jul 02 21:33:13 volumio2 volumio[1029]: verbose: ControllerMpd::parseTrackInfo Jul 02 21:33:13 volumio2 volumio[1029]: info: ControllerMpd::pushState Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreCommandRouter::servicePushState Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreStateMachine::pushState Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:33:13 volumio2 volumio[1029]: info: CorePlayQueue::getTrack 0 Jul 02 21:33:13 volumio2 volumio[1029]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Kiss","artist":"Tony Desare","album":"Last First Kiss","uri":"http://192.168.1.20:17391/qobuz/182515633.flac","trackType":"qobuz"} Jul 02 21:33:13 volumio2 volumio[1029]: verbose: CURRENT POSITION 0 Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreStateMachine::syncState stateService stop Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreStateMachine::syncState currentStatus play Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreCommandRouter::volumioPushState Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreStateMachine::stPlaybackTimer Jul 02 21:33:13 volumio2 volumio[1029]: info: ------------------------------ 11ms Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:33:13 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:33:13 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:33:15 volumio2 volumio[1029]: info: Getting Spotify volume Jul 02 21:33:15 volumio2 volumio[1029]: (node:1029) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:15 volumio2 volumio[1029]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 02 21:33:15 volumio2 volumio[1029]: (node:1029) 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: 15) Jul 02 21:33:15 volumio2 volumio[1029]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jul 02 21:33:15 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:15 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:15 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:15 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:15 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 52. Jul 02 21:33:15 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:15 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:15 volumio2 go-librespot[3013]: Librespot-go daemon starting... Jul 02 21:33:15 volumio2 go-librespot[3013]: time="2025-07-02T21:33:15+07:00" level=info msg="generated new device id: 77c5e12a665292057a61c45f974c0b29419e3331" Jul 02 21:33:15 volumio2 go-librespot[3013]: time="2025-07-02T21:33:15+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:15 volumio2 go-librespot[3013]: time="2025-07-02T21:33:15+07:00" level=debug msg="obtained new client token: AAAHMZATsGiTxtkw962oRun9jkTFRKxHQn+UZ0ujdElpAoAxkaqTBTtVAfkahghjdGUXJMAjKmlY+v9veEQPUxRP8l/F1I2xa9XHH8WaJG9uwwkeRcqjmrDq97v7CRg21yY0s31NGwb7tQAl9Z58I+4lhx/Swpt21fqzn/ixq1ZZ/vNLEzGpEsi4wFllnb8qq1d1J0lb52RA7oTurCuLnQikR5cW2MpHo43UaImH+yTMMbci5uXsgiyfC1Ka" Jul 02 21:33:15 volumio2 go-librespot[3013]: time="2025-07-02T21:33:15+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:33:15 volumio2 go-librespot[3013]: time="2025-07-02T21:33:15+07:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.241.202:4070: connect: connection refused" Jul 02 21:33:15 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:15 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:18 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:18 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:19 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:19 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 53. Jul 02 21:33:19 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:19 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:19 volumio2 go-librespot[3034]: Librespot-go daemon starting... Jul 02 21:33:19 volumio2 go-librespot[3034]: time="2025-07-02T21:33:19+07:00" level=info msg="generated new device id: 2fba241e0334d5714f53c87a33c151948b90132d" Jul 02 21:33:19 volumio2 go-librespot[3034]: time="2025-07-02T21:33:19+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:19 volumio2 go-librespot[3034]: time="2025-07-02T21:33:19+07:00" level=debug msg="obtained new client token: AAAmUPxkgShepCxgFNDc6yHg8UxCuc8GwMrlwrd3qTgobvs1VS+ezUXBcx9qnF3lmsXeJ1nCKgHZX/xk271JGjwTgNzqVM2pUh9A93JvNBurggmV02C0cvTsoNk/Bez57Dws16HkwGYBbR5tiyg2GCSDXfjnMneIDhAVk6+/YfJOvNVUT3EDCbaJkDhD0n1h1/NeaF8aaI+OS3/wlyhuXo5bbFUYXRSA4lVNz57X+SyIlZAGjhs5ygNjFw==" Jul 02 21:33:19 volumio2 go-librespot[3034]: time="2025-07-02T21:33:19+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:33:19 volumio2 go-librespot[3034]: time="2025-07-02T21:33:19+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:19 volumio2 go-librespot[3034]: time="2025-07-02T21:33:19+07:00" level=debug msg="completed challenge" Jul 02 21:33:19 volumio2 go-librespot[3034]: time="2025-07-02T21:33:19+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:20 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:20 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 02 21:33:21 volumio2 volumio[1029]: info: Discovery: Getting this device information Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 02 21:33:21 volumio2 volumio[1029]: info: Discovery: Getting this device information Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:21 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 02 21:33:21 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:21 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:22 volumio2 volumio[1029]: verbose: New Socket.io Connection to 192.168.1.13:3000 from 192.168.1.20 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Jul 02 21:33:22 volumio2 volumio[1029]: verbose: New Socket.io Connection to 192.168.1.13 from 192.168.1.20 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8 Jul 02 21:33:22 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:22 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 02 21:33:22 volumio2 volumio[1029]: info: Listing playlists Jul 02 21:33:22 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetVisibleSources Jul 02 21:33:22 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 02 21:33:22 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:33:22 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:33:22 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:33:23 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:23 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 54. Jul 02 21:33:23 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:23 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:23 volumio2 go-librespot[3041]: Librespot-go daemon starting... Jul 02 21:33:23 volumio2 go-librespot[3041]: time="2025-07-02T21:33:23+07:00" level=info msg="generated new device id: 9e0165eb5faa63a0bbffb3a9a2de8bd7b21d7a09" Jul 02 21:33:23 volumio2 go-librespot[3041]: time="2025-07-02T21:33:23+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:23 volumio2 go-librespot[3041]: time="2025-07-02T21:33:23+07:00" level=debug msg="obtained new client token: AACRLShIpKuCnNTH4yPmrLcCBFenhhDahOfdsJQfGSYZd9qHoB6WunO0IfPJiDR6OcnwM+oWbVCQyx1QQv/Mdd6w/uYvprM1X6nSfIQp8lKTwhrWs9TzdjULLuZjsGwDPGhM/oM4g5diIFlgJyNNwe/2It0Kgy7jWcOqrelIEH+UXGS5C/kleAsX0Ccu8bu9fAfI9P2Pg91lxaAc91l/JucysRO2pSqoEkKRstK38wFvdfPhzlwTqiQ8kw==" Jul 02 21:33:23 volumio2 go-librespot[3041]: time="2025-07-02T21:33:23+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:33:23 volumio2 go-librespot[3041]: time="2025-07-02T21:33:23+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:24 volumio2 go-librespot[3041]: time="2025-07-02T21:33:24+07:00" level=debug msg="completed challenge" Jul 02 21:33:24 volumio2 go-librespot[3041]: time="2025-07-02T21:33:24+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:24 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:24 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:24 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:24 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:25 volumio2 sudo[3049]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 02 21:33:25 volumio2 sudo[3049]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 02 21:33:25 volumio2 sudo[3049]: pam_unix(sudo:session): session closed for user root Jul 02 21:33:25 volumio2 sudo[3052]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 02 21:33:25 volumio2 sudo[3052]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 02 21:33:25 volumio2 sudo[3052]: pam_unix(sudo:session): session closed for user root Jul 02 21:33:25 volumio2 volumio[1029]: verbose: New Socket.io Connection to 192.168.1.13 from 192.168.1.20 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetVisibleSources Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 02 21:33:25 volumio2 sudo[3055]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 02 21:33:25 volumio2 sudo[3055]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 02 21:33:25 volumio2 sudo[3055]: pam_unix(sudo:session): session closed for user root Jul 02 21:33:25 volumio2 sudo[3058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 02 21:33:25 volumio2 sudo[3058]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 02 21:33:25 volumio2 sudo[3058]: pam_unix(sudo:session): session closed for user root Jul 02 21:33:25 volumio2 volumio[1029]: verbose: New Socket.io Connection to 192.168.1.13 from 192.168.1.20 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_5 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 9 Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 02 21:33:25 volumio2 volumio[1029]: info: Listing playlists Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Jul 02 21:33:25 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 02 21:33:27 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:27 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 55. Jul 02 21:33:27 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:27 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:27 volumio2 go-librespot[3060]: Librespot-go daemon starting... Jul 02 21:33:27 volumio2 go-librespot[3060]: time="2025-07-02T21:33:27+07:00" level=info msg="generated new device id: 161463fa37df83f6d49baabde8a675fed183e716" Jul 02 21:33:27 volumio2 go-librespot[3060]: time="2025-07-02T21:33:27+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:27 volumio2 go-librespot[3060]: time="2025-07-02T21:33:27+07:00" level=debug msg="obtained new client token: AAAU+SnLGzgPo13ZSJRvgl/h8Cxh8e/g0S5T5Q09BUVqj1yzUrUv9SIxmYnJFrW7/pjXPyV54/i9JJcVjIVW3X/k3qzn/Cru9UbZsf2WYjCiPmoOO5610Ey0ydQ/JystpwOpHz05g7aFy0QeV1Gzkz+LedzHxW1ePlxc8dqXlvLJg46hb14u3Hy6X7WGBVjCsRy1Mo/SF9D992tvqNODEmu+C9e7dCaq/6BQ2a/KU7UOIChPC1n/Ydyy39so" Jul 02 21:33:27 volumio2 go-librespot[3060]: time="2025-07-02T21:33:27+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:33:27 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:27 volumio2 go-librespot[3060]: time="2025-07-02T21:33:27+07:00" level=debug msg="new websocket client" Jul 02 21:33:27 volumio2 volumio[1029]: info: Connection to go-librespot Websocket established Jul 02 21:33:27 volumio2 go-librespot[3060]: time="2025-07-02T21:33:27+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:27 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetVisibleSources Jul 02 21:33:27 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 02 21:33:27 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetQueue Jul 02 21:33:27 volumio2 volumio[1029]: info: CoreStateMachine::getQueue Jul 02 21:33:27 volumio2 volumio[1029]: info: CorePlayQueue::getQueue Jul 02 21:33:28 volumio2 go-librespot[3060]: time="2025-07-02T21:33:28+07:00" level=debug msg="completed challenge" Jul 02 21:33:28 volumio2 go-librespot[3060]: time="2025-07-02T21:33:28+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:28 volumio2 volumio[1029]: info: Connection to go-librespot Websocket closed Jul 02 21:33:28 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:28 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:30 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 02 21:33:30 volumio2 volumio[1029]: info: Received Get System Info Jul 02 21:33:30 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 02 21:33:30 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 02 21:33:30 volumio2 volumio[1029]: info: Discovery: Getting this device information Jul 02 21:33:30 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:30 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 02 21:33:30 volumio2 volumio[1029]: info: Getting Spotify volume Jul 02 21:33:30 volumio2 volumio[1029]: (node:1029) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:30 volumio2 volumio[1029]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Jul 02 21:33:30 volumio2 volumio[1029]: (node:1029) 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: 16) Jul 02 21:33:30 volumio2 volumio[1029]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Jul 02 21:33:30 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:31 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:31 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 02 21:33:31 volumio2 volumio[1029]: info: Retrieving Cloud Streaming UI Jul 02 21:33:31 volumio2 volumio[1029]: info: Getting Tidal Cloud Configuration Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 02 21:33:31 volumio2 volumio[1029]: info: Getting Qobuz Cloud Configuration Jul 02 21:33:31 volumio2 volumio[1029]: info: Asking plugin for UI Config Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 02 21:33:31 volumio2 volumio[1029]: info: Getting Spotify Cloud Configuration Jul 02 21:33:31 volumio2 volumio[1029]: info: Asking plugin for UI Config Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 02 21:33:31 volumio2 volumio[1029]: info: Saving Spotify Acccount Jul 02 21:33:31 volumio2 volumio[1029]: info: Got Tidal Cloud Configuration Jul 02 21:33:31 volumio2 volumio[1029]: info: Got it Jul 02 21:33:31 volumio2 volumio[1029]: info: Got it Jul 02 21:33:31 volumio2 volumio[1029]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 02 21:33:31 volumio2 volumio[1029]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetBrowseSources Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetBrowseSources Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetBrowseSources Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 02 21:33:31 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jul 02 21:33:31 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:31 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 56. Jul 02 21:33:31 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:31 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:31 volumio2 go-librespot[3128]: Librespot-go daemon starting... Jul 02 21:33:31 volumio2 go-librespot[3128]: time="2025-07-02T21:33:31+07:00" level=info msg="generated new device id: a222ac2ff1a70ae7fd6d717e82e4db3b2c0a4292" Jul 02 21:33:31 volumio2 go-librespot[3128]: time="2025-07-02T21:33:31+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:31 volumio2 go-librespot[3128]: time="2025-07-02T21:33:31+07:00" level=debug msg="obtained new client token: AABWH0J/HIAiqPxk6FDZJEw9FG5Y6UgJ13GOFOlRTgeEH+z5p4FVaMwS3rEJ3BkS790F9+eb2EIVjI65sOYUAkYEjp/KnjMS0+iic7ZZ1tY5Rh//RQrB/rTxfWFAle6AFfo5iSOKTa1amaLq30iYW/vKhHp+VZoyfqUjYpBaeKnsoaZ3dAJ2Cl30Bp5u81BtbfOS2sW/ysH7i10QB4ea/t+ifLNkVJpmr2N7jycXmr3bCKQXxd9pa69dk5gH" Jul 02 21:33:31 volumio2 go-librespot[3128]: time="2025-07-02T21:33:31+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 02 21:33:31 volumio2 go-librespot[3128]: time="2025-07-02T21:33:31+07:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 104.199.241.202:4070: connect: connection refused" Jul 02 21:33:31 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:31 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:34 volumio2 volumio[1029]: info: Disabling MyMusic plugin upnp Jul 02 21:33:34 volumio2 sudo[3136]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jul 02 21:33:34 volumio2 sudo[3136]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 02 21:33:34 volumio2 systemd[1]: Stopping UPnP Renderer front-end to MPD... Jul 02 21:33:34 volumio2 volumio[1029]: error: Upnp client error: Error: This socket has been ended by the other party Jul 02 21:33:34 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:34 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:34 volumio2 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 02 21:33:34 volumio2 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57. Jul 02 21:33:34 volumio2 systemd[1]: Stopped go-librespot Daemon. Jul 02 21:33:34 volumio2 systemd[1]: Started go-librespot Daemon. Jul 02 21:33:34 volumio2 go-librespot[3138]: Librespot-go daemon starting... Jul 02 21:33:34 volumio2 go-librespot[3138]: time="2025-07-02T21:33:34+07:00" level=info msg="generated new device id: 6314682fa0e779d18745419eb8e20a257ccf1928" Jul 02 21:33:34 volumio2 go-librespot[3138]: time="2025-07-02T21:33:34+07:00" level=debug msg="stored credentials found for tp20pocsknlcll7n6w5hgfvb0" Jul 02 21:33:35 volumio2 go-librespot[3138]: time="2025-07-02T21:33:35+07:00" level=debug msg="obtained new client token: AACwp6NOtE3XPhft3D2pbanFj93YTAv9k3C+vV3LDL7B1YdQ2az8m4Z2H4SAlP1roP8MPu+nFcFaR2DhF3GuHSBlO3mqQHxc6ytDgdSlzhAEikr2kh0pgNJpwZaNvFBqfU3Is0HvqFnx3xh41k8Hz4/wGhnoKs88QGoEsUwSb9gZkHaZZyHrMe2je0ato/Gq4ud7WSSoCgU1gQhEuQMxadPnyVGxeeIx0nmSUSP0IKrM6XNRiE90PUHuUA==" Jul 02 21:33:35 volumio2 go-librespot[3138]: time="2025-07-02T21:33:35+07:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 02 21:33:35 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 02 21:33:35 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 02 21:33:35 volumio2 volumio[1029]: info: Discovery: Getting this device information Jul 02 21:33:35 volumio2 volumio[1029]: info: CoreCommandRouter::volumioGetState Jul 02 21:33:35 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 02 21:33:35 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 02 21:33:35 volumio2 go-librespot[3138]: time="2025-07-02T21:33:35+07:00" level=debug msg="completed keyexchange" Jul 02 21:33:36 volumio2 go-librespot[3138]: time="2025-07-02T21:33:36+07:00" level=debug msg="completed challenge" Jul 02 21:33:36 volumio2 go-librespot[3138]: time="2025-07-02T21:33:36+07:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Jul 02 21:33:36 volumio2 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 02 21:33:36 volumio2 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 02 21:33:37 volumio2 volumio[1029]: info: Initializing connection to go-librespot Websocket Jul 02 21:33:37 volumio2 volumio[1029]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 02 21:33:39 volumio2 volumio[1029]: info: Enabling MyMusic plugin upnp Jul 02 21:33:39 volumio2 volumio[1029]: info: Enabling plugin upnp Jul 02 21:33:39 volumio2 volumio[1029]: info: Loading plugin "upnp"... Jul 02 21:33:39 volumio2 volumio[1029]: info: [1751466819054] Starting Upmpd Daemon Jul 02 21:33:39 volumio2 volumio[1029]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 02 21:33:39 volumio2 volumio[1029]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 02 21:33:39 volumio2 volumio[1029]: Error: listen EADDRINUSE: address already in use :::6599 Jul 02 21:33:39 volumio2 volumio[1029]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Jul 02 21:33:39 volumio2 volumio[1029]: at listenInCluster (net.js:1379:12) Jul 02 21:33:39 volumio2 volumio[1029]: at Server.listen (net.js:1465:7) Jul 02 21:33:39 volumio2 volumio[1029]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Jul 02 21:33:39 volumio2 volumio[1029]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Jul 02 21:33:39 volumio2 volumio[1029]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jul 02 21:33:39 volumio2 volumio[1029]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jul 02 21:33:39 volumio2 volumio[1029]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Jul 02 21:33:39 volumio2 volumio[1029]: code: 'EADDRINUSE', Jul 02 21:33:39 volumio2 volumio[1029]: errno: -98, Jul 02 21:33:39 volumio2 volumio[1029]: syscall: 'listen', Jul 02 21:33:39 volumio2 volumio[1029]: address: '::', Jul 02 21:33:39 volumio2 volumio[1029]: port: 6599 Jul 02 21:33:39 volumio2 volumio[1029]: } Jul 02 21:33:39 volumio2 volumio[1029]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 02 21:33:39 volumio2 sudo[3169]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-02 21:32 Jul 02 21:33:39 volumio2 sudo[3169]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 05:26:48 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="a63f40325536655a08b14de2b295ce76"