-- Logs begin at Sat 2024-10-12 10:02:21 CEST, end at Sat 2024-10-12 13:02:14 CEST. -- Oct 12 13:01:01 volumio go-librespot[27606]: time="2024-10-12T13:01:01+02:00" level=debug msg="obtained new client token: AAA6bE0SCStuRTk7tx3l9MnIiqYfUoTpz91VTjcyjEKH3/HYMZvmKAWexXGbQzzujVNuAbCuscdTYj5jmq1eJddFTWXqT5d7KRzrYsU27lkns8EJxNHhNUQIiKjGi1NaR01GxO6i8a+GUpKxGWm2SuCpyh3K5wg71WblOT8qGzyPGsIKq35DClMlR/LXiINU8UFM5Ey7LSNg3636cruPGRAHbtcUZIqCsh7fNSzbEBA7QIwbUjs2raRcbyA8FRY=" Oct 12 13:01:01 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:01 volumio volumio[671]: info: Listing playlists Oct 12 13:01:01 volumio volumio[671]: info: Listing playlists Oct 12 13:01:01 volumio go-librespot[27606]: time="2024-10-12T13:01:01+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 12 13:01:01 volumio go-librespot[27606]: time="2024-10-12T13:01:01+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:02 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:02 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:01:02 volumio go-librespot[27606]: time="2024-10-12T13:01:02+02:00" level=debug msg="new websocket client" Oct 12 13:01:02 volumio go-librespot[27606]: time="2024-10-12T13:01:02+02:00" level=debug msg="completed challenge" Oct 12 13:01:02 volumio go-librespot[27606]: time="2024-10-12T13:01:02+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:02 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:02 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:02 volumio volumio[671]: info: Connection to go-librespot Websocket closed Oct 12 13:01:05 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:01:05 volumio volumio[671]: (node:671) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:05 volumio volumio[671]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 12 13:01:05 volumio volumio[671]: (node:671) 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: 38030) Oct 12 13:01:05 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:01:05 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:05 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:05 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:05 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:05 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57626. Oct 12 13:01:05 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:05 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:05 volumio go-librespot[27636]: Librespot-go daemon starting... Oct 12 13:01:05 volumio go-librespot[27636]: time="2024-10-12T13:01:05+02:00" level=info msg="generated new device id: 43feaa3436ae8026c3807a04e256128c7326e62f" Oct 12 13:01:05 volumio go-librespot[27636]: time="2024-10-12T13:01:05+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:07 volumio go-librespot[27636]: time="2024-10-12T13:01:07+02:00" level=debug msg="obtained new client token: AAAGAt4w/T+4COdgzEIkl2RfwMslzHiA6U+quzaLygCx1FCq2MMQ9TtxE8fRxEoB/aimj34XdvrG8EKwaQETwPaf/lnmPpClNjPf2Er2vhTvxWDQangn2QBmwKmBICD14mRpQK+99b2sF5AEuXzA6gyB95IvHjgwiahtD9iV6wImBXO80yhQ0s7+3ihjpdEM4WN+GxUTBd4dQZNz2nYTtbDgry/mHdBxZ86Pn7GcD31JwzXzEhQ2r1k61Qm4czDbbQ==" Oct 12 13:01:07 volumio go-librespot[27636]: time="2024-10-12T13:01:07+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 12 13:01:08 volumio go-librespot[27636]: time="2024-10-12T13:01:08+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:08 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:08 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:01:08 volumio go-librespot[27636]: time="2024-10-12T13:01:08+02:00" level=debug msg="new websocket client" Oct 12 13:01:08 volumio go-librespot[27636]: time="2024-10-12T13:01:08+02:00" level=debug msg="completed challenge" Oct 12 13:01:08 volumio go-librespot[27636]: time="2024-10-12T13:01:08+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:08 volumio volumio[671]: info: Connection to go-librespot Websocket closed Oct 12 13:01:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:10 volumio volumio[671]: info: Oct 12 13:01:10 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:10 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:10 volumio volumio[671]: info: Oct 12 13:01:10 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:01:10 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:01:10 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:01:10 volumio volumio[671]: info: Oct 12 13:01:10 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:10 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:10 volumio volumio[671]: info: Oct 12 13:01:10 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:01:10 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:01:10 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:01:10 volumio volumio[671]: info: Oct 12 13:01:10 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:10 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:10 volumio volumio[671]: info: Oct 12 13:01:10 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:01:10 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:01:10 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:01:10 volumio volumio[671]: info: ------------------------------ 119ms Oct 12 13:01:10 volumio volumio[671]: info: sendMpdCommand status took 90 milliseconds Oct 12 13:01:10 volumio volumio[671]: info: ------------------------------ 89ms Oct 12 13:01:11 volumio volumio[671]: info: sendMpdCommand status took 71 milliseconds Oct 12 13:01:11 volumio volumio[671]: info: ------------------------------ 70ms Oct 12 13:01:11 volumio volumio[671]: info: sendMpdCommand status took 53 milliseconds Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:01:11 volumio volumio[671]: info: sendMpdCommand playlistinfo took 39 milliseconds Oct 12 13:01:11 volumio volumio[671]: info: sendMpdCommand playlistinfo took 35 milliseconds Oct 12 13:01:11 volumio volumio[671]: info: sendMpdCommand playlistinfo took 30 milliseconds Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:01:11 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:01:11 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:01:11 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:11 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":770168,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"instagram.com/radioparty.pl/","artist":"RadioParty.pl - najlepsze party w sieci","album":null,"uri":"https://s2.radioparty.pl:8015/stream","trackType":""} Oct 12 13:01:11 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:01:11 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:11 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:01:11 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:11 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":770168,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"instagram.com/radioparty.pl/","artist":"RadioParty.pl - najlepsze party w sieci","album":null,"uri":"https://s2.radioparty.pl:8015/stream","trackType":""} Oct 12 13:01:11 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:01:11 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:11 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:01:11 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:11 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":770168,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"instagram.com/radioparty.pl/","artist":"RadioParty.pl - najlepsze party w sieci","album":null,"uri":"https://s2.radioparty.pl:8015/stream","trackType":""} Oct 12 13:01:11 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:01:11 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:11 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:11 volumio volumio[671]: info: ------------------------------ 500ms Oct 12 13:01:11 volumio volumio[671]: info: ------------------------------ 473ms Oct 12 13:01:11 volumio volumio[671]: info: ------------------------------ 448ms Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:11 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:01:11 volumio volumio[671]: (node:671) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:11 volumio volumio[671]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 12 13:01:11 volumio volumio[671]: (node:671) 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: 38031) Oct 12 13:01:11 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:01:11 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:11 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:11 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57627. Oct 12 13:01:12 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:12 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:12 volumio go-librespot[27667]: Librespot-go daemon starting... Oct 12 13:01:12 volumio go-librespot[27667]: time="2024-10-12T13:01:12+02:00" level=info msg="generated new device id: e57ccfb193ae8c86c72a758fb9a7d0d67968e043" Oct 12 13:01:12 volumio go-librespot[27667]: time="2024-10-12T13:01:12+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:13 volumio go-librespot[27667]: time="2024-10-12T13:01:13+02:00" level=debug msg="obtained new client token: AAAD+y4CnU0dhl1UXEnPivMuvHPS53RK9L6ijqoe0znszA8K9yiRxZIFyXDRQi6aFeYoj3zXKnUuLG2FQW0lzsimWHTaHocPiZ/5815EHwqZpFsRVj6+gQ2u9AWoGlI6AYaOeNO14wcGRe+07fD74jpddKAtth/M5LMBAVUAkU0fUYjI+q+E1VyZn6zxx/ho4WjhojG92UkzOHVV1jwEa1bMLwXlaMOivcm5reyI0Y5Le8GFgaxNzvTTgjxSaZNtyg==" Oct 12 13:01:14 volumio go-librespot[27667]: time="2024-10-12T13:01:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 12 13:01:14 volumio go-librespot[27667]: time="2024-10-12T13:01:14+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:14 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:14 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:01:14 volumio go-librespot[27667]: time="2024-10-12T13:01:14+02:00" level=debug msg="new websocket client" Oct 12 13:01:14 volumio go-librespot[27667]: time="2024-10-12T13:01:14+02:00" level=debug msg="completed challenge" Oct 12 13:01:15 volumio go-librespot[27667]: time="2024-10-12T13:01:15+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:15 volumio volumio[671]: info: Connection to go-librespot Websocket closed Oct 12 13:01:17 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:01:18 volumio volumio[671]: (node:671) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:18 volumio volumio[671]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 12 13:01:18 volumio volumio[671]: (node:671) 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: 38032) Oct 12 13:01:18 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:01:18 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:18 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:18 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57628. Oct 12 13:01:18 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:18 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:18 volumio go-librespot[27684]: Librespot-go daemon starting... Oct 12 13:01:18 volumio go-librespot[27684]: time="2024-10-12T13:01:18+02:00" level=info msg="generated new device id: 36d2b430283719466ff4aa94673023f06ae73959" Oct 12 13:01:18 volumio go-librespot[27684]: time="2024-10-12T13:01:18+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:19 volumio go-librespot[27684]: time="2024-10-12T13:01:19+02:00" level=debug msg="obtained new client token: AADZ+xyJyx3ZTwNOps3JS218a4SaXqc73DKIIaErE+rOZlazbqAINZMBcY/d5jY1SQPV7wyyfHJalDGVMzrAwgD/SIrMLDanS9gGKb1fX1wjnvwAEVQj5mtCgomOfbyStQfBkrsZVV7uOet4DqvIaphhU5ePbBqlTLKluewa+3TtZPBPO6xjt4YMMh75/BZvxhHQwcHu4DULYLtZzajUb6ple75TWJ+SW6UkXzmWk+Qn2VPyLozwhliYEl5xzvXaXA==" Oct 12 13:01:20 volumio go-librespot[27684]: time="2024-10-12T13:01:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 12 13:01:20 volumio go-librespot[27684]: time="2024-10-12T13:01:20+02:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Oct 12 13:01:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:21 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:21 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:21 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:21 volumio volumio[671]: info: Listing playlists Oct 12 13:01:21 volumio volumio[671]: info: Listing playlists Oct 12 13:01:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57629. Oct 12 13:01:23 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:23 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:23 volumio go-librespot[27712]: Librespot-go daemon starting... Oct 12 13:01:23 volumio go-librespot[27712]: time="2024-10-12T13:01:23+02:00" level=info msg="generated new device id: af489b00874ad7beb3b7b51a2c7dfae54fda5248" Oct 12 13:01:23 volumio go-librespot[27712]: time="2024-10-12T13:01:23+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:24 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:24 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:01:24 volumio go-librespot[27712]: time="2024-10-12T13:01:24+02:00" level=debug msg="new websocket client" Oct 12 13:01:26 volumio go-librespot[27712]: time="2024-10-12T13:01:26+02:00" level=debug msg="obtained new client token: AAA1irYDAtBlvAIyHQw1d4Rt1YLFQIsqK6FiQdvF9qHYvWHF8cxA0sgJnAcgP6XS+SEmFu54oXk/J08GCB0NXZW30Hv1T98NE+oDE8RxKNqeC4tUP8WSntZnK/4+7SlSQThLCA72BdqU5D0qELboplglW5sk3U9ZWzO3JiDwIgKSI+GgStiFKlSGgEWKSnBbzq8+V9KqvchnBCZEtKwqB1TjDp/x2CnC5ZSjVHYNzevjlamD+zF/Z+iB6KgUp/s=" Oct 12 13:01:26 volumio go-librespot[27712]: time="2024-10-12T13:01:26+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 12 13:01:26 volumio go-librespot[27712]: time="2024-10-12T13:01:26+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:27 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:01:27 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:01:27 volumio go-librespot[27712]: time="2024-10-12T13:01:27+02:00" level=debug msg="completed challenge" Oct 12 13:01:27 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:27 volumio go-librespot[27712]: time="2024-10-12T13:01:27+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:27 volumio volumio[671]: (node:671) UnhandledPromiseRejectionWarning: Error: socket hang up Oct 12 13:01:27 volumio volumio[671]: at connResetException (internal/errors.js:607:14) Oct 12 13:01:27 volumio volumio[671]: at Socket.socketOnEnd (_http_client.js:493:23) Oct 12 13:01:27 volumio volumio[671]: at Socket.emit (events.js:327:22) Oct 12 13:01:27 volumio volumio[671]: at endReadableNT (internal/streams/readable.js:1327:12) Oct 12 13:01:27 volumio volumio[671]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Oct 12 13:01:27 volumio volumio[671]: (node:671) 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: 38033) Oct 12 13:01:27 volumio volumio[671]: info: Connection to go-librespot Websocket closed Oct 12 13:01:30 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57630. Oct 12 13:01:30 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:30 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:30 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:30 volumio go-librespot[27773]: Librespot-go daemon starting... Oct 12 13:01:30 volumio go-librespot[27773]: time="2024-10-12T13:01:30+02:00" level=info msg="generated new device id: e86fb5a25b565316ca020cc5a7cbb0392ee1e777" Oct 12 13:01:30 volumio go-librespot[27773]: time="2024-10-12T13:01:30+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:31 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:32 volumio go-librespot[27773]: time="2024-10-12T13:01:32+02:00" level=debug msg="obtained new client token: AACPZ6CLSHjuift1EIswNx+K0Gms5vVttILCbUENiT8WyD87yIM26WurCf78QkCgyjrrPNmmBvUid6MVqZhOy2LMpXVVSUiqrYICguFm6enNzV+VSFMwAbDEYeoL6hqwfx6mMlxTxkWnESNBQEYAlgyQaMN1f6/L9aDJmVz36JYTIrgM0ESdkSX/CJD11A+oEXk7P5PjrR5kfSVeZO8ZYGdFI9Wto/YwGeW7mnGiPXewIeHjaAO8+Qt025pBqeFR6A==" Oct 12 13:01:32 volumio go-librespot[27773]: time="2024-10-12T13:01:32+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 12 13:01:33 volumio go-librespot[27773]: time="2024-10-12T13:01:33+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:33 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:33 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:01:33 volumio go-librespot[27773]: time="2024-10-12T13:01:33+02:00" level=debug msg="new websocket client" Oct 12 13:01:33 volumio go-librespot[27773]: time="2024-10-12T13:01:33+02:00" level=debug msg="completed challenge" Oct 12 13:01:33 volumio go-librespot[27773]: time="2024-10-12T13:01:33+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:33 volumio volumio[671]: info: Connection to go-librespot Websocket closed Oct 12 13:01:36 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:01:36 volumio volumio[671]: (node:671) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:36 volumio volumio[671]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 12 13:01:36 volumio volumio[671]: (node:671) 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: 38034) Oct 12 13:01:36 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:01:36 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:36 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:36 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57631. Oct 12 13:01:36 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:37 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:37 volumio go-librespot[27802]: Librespot-go daemon starting... Oct 12 13:01:37 volumio go-librespot[27802]: time="2024-10-12T13:01:37+02:00" level=info msg="generated new device id: 6c158938469df5fb7514514c861aba0e9ad283f3" Oct 12 13:01:37 volumio go-librespot[27802]: time="2024-10-12T13:01:37+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:38 volumio go-librespot[27802]: time="2024-10-12T13:01:38+02:00" level=debug msg="obtained new client token: AABxZqd2g03QDnOLqO6Mc5bWImx4P5z4fcaN+MEsLDXSKotUI7EOKTKibYbE9wDinS17m5+3N6Thd80olM/+N+7GWrbsw0BRJ11irKzPc2sYL3+KyMSLn6ysrBOtvEk7AEqp8MSY4zwrLSD8XoDR9XCQ3Ea8VcFWUp33HtPRNtrhY9XPnjy0IiUuctC8MMAk4/Xjf0dkiwVuFdN7bEpvTtqQhgqhx3+/XsbRjKOxXN7f7EHTKy+sRlHuOVVcJ8SDqQ==" Oct 12 13:01:38 volumio go-librespot[27802]: time="2024-10-12T13:01:38+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 12 13:01:39 volumio go-librespot[27802]: time="2024-10-12T13:01:39+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:39 volumio go-librespot[27802]: time="2024-10-12T13:01:39+02:00" level=debug msg="completed challenge" Oct 12 13:01:39 volumio go-librespot[27802]: time="2024-10-12T13:01:39+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:39 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:39 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:42 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:42 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57632. Oct 12 13:01:42 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:42 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:43 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:43 volumio go-librespot[27820]: Librespot-go daemon starting... Oct 12 13:01:43 volumio go-librespot[27820]: time="2024-10-12T13:01:43+02:00" level=info msg="generated new device id: 4dff52d381ce66e8f98e1081b49cb6f5d02f7524" Oct 12 13:01:43 volumio go-librespot[27820]: time="2024-10-12T13:01:43+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:43 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:43 volumio volumio[671]: info: Listing playlists Oct 12 13:01:43 volumio volumio[671]: info: Listing playlists Oct 12 13:01:44 volumio go-librespot[27820]: time="2024-10-12T13:01:44+02:00" level=debug msg="obtained new client token: AABnq7ele4JyPO3s8U8nbSal9KL4JZebdUMZYhS1/KPkM8OTn8ch7CtWw9wCUhYpXJQLbf47zGHVgjtbhrihiGIEaPVlDtR+BZ88gUPcyXgYLcClEwNxrF+kmzn61GuSrJ3TsEfBBTYFmTzLp5MnoeR5pelpS1q93udkjgm2kbIQtKyUhDWhRY698kyjkBFjjrITpG3nWCSBFKlAhewpgXXLJlpC73mr28CvLiNvrZ3nB2OFj9d8D0qzxCfNXAdFlQ==" Oct 12 13:01:45 volumio go-librespot[27820]: time="2024-10-12T13:01:45+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 12 13:01:45 volumio go-librespot[27820]: time="2024-10-12T13:01:45+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:45 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:45 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:01:45 volumio go-librespot[27820]: time="2024-10-12T13:01:45+02:00" level=debug msg="new websocket client" Oct 12 13:01:46 volumio go-librespot[27820]: time="2024-10-12T13:01:46+02:00" level=debug msg="completed challenge" Oct 12 13:01:46 volumio go-librespot[27820]: time="2024-10-12T13:01:46+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:46 volumio volumio[671]: info: Connection to go-librespot Websocket closed Oct 12 13:01:46 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:46 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:49 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:01:49 volumio volumio[671]: (node:671) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:49 volumio volumio[671]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 12 13:01:49 volumio volumio[671]: (node:671) 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: 38035) Oct 12 13:01:49 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:01:49 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:49 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:49 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57633. Oct 12 13:01:49 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:49 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:49 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:49 volumio go-librespot[27850]: Librespot-go daemon starting... Oct 12 13:01:49 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:49 volumio go-librespot[27850]: time="2024-10-12T13:01:49+02:00" level=info msg="generated new device id: 1c2af2ec1be3d7fd1a8cbf2365e6d49f456249f5" Oct 12 13:01:49 volumio go-librespot[27850]: time="2024-10-12T13:01:49+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:51 volumio go-librespot[27850]: time="2024-10-12T13:01:51+02:00" level=debug msg="obtained new client token: AAC2VWaq/0xwfTWNxk3UprUgNR5/acC5mcXH2X42Oo4LrcPVfvT4qhV2KttCZWvr2e/HGWce2oywd8l6JdHQImIR+59K08uqcatxgaGOW5uO8wR+9gDlLIEbeB3x3T1m4jxraMH898qWrQzmr7VXqJ6AuWM5wmSlU7du18Qy/QSykrYvmiPnoyFEa4QnMXiNAYQ7u7OKkm9hfVL3Cv1xkiwHqpp242DukED2low1Re3TfYuLxdkiJfTdHdwwIiOXeQ==" Oct 12 13:01:51 volumio go-librespot[27850]: time="2024-10-12T13:01:51+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 12 13:01:52 volumio volumio[671]: info: Clearing queue after UPNP request Oct 12 13:01:52 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:52 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:01:52 volumio go-librespot[27850]: time="2024-10-12T13:01:52+02:00" level=debug msg="new websocket client" Oct 12 13:01:52 volumio volumio[671]: info: CoreStateMachine::ClearQueue Oct 12 13:01:52 volumio volumio[671]: info: CoreStateMachine::stop Oct 12 13:01:52 volumio volumio[671]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 12 13:01:52 volumio volumio[671]: info: CoreStateMachine::stPlaybackTimer Oct 12 13:01:52 volumio volumio[671]: info: CoreStateMachine::updateTrackBlock Oct 12 13:01:52 volumio volumio[671]: info: CorePlayQueue::getTrackBlock Oct 12 13:01:52 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:52 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:52 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 13:01:52 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:52 volumio volumio[671]: info: CoreStateMachine::serviceStop Oct 12 13:01:52 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:52 volumio volumio[671]: info: CoreCommandRouter::serviceStop Oct 12 13:01:52 volumio volumio[671]: info: [1728730912750] ControllerWebradio::stop Oct 12 13:01:52 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand stop Oct 12 13:01:52 volumio volumio[671]: info: CorePlayQueue::clearPlayQueue Oct 12 13:01:52 volumio volumio[671]: info: CorePlayQueue::saveQueue Oct 12 13:01:52 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:52 volumio volumio[671]: info: CoreCommandRouter::volumioPushQueue Oct 12 13:01:52 volumio go-librespot[27850]: time="2024-10-12T13:01:52+02:00" level=debug msg="completed keyexchange" Oct 12 13:01:53 volumio volumio[671]: info: Oct 12 13:01:53 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:01:53 volumio volumio[671]: info: sendMpdCommand stop took 273 milliseconds Oct 12 13:01:53 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:01:53 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:01:53 volumio volumio[671]: info: Oct 12 13:01:53 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:01:53 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:01:53 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:01:53 volumio volumio[671]: info: Oct 12 13:01:53 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:01:53 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:01:53 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:01:53 volumio volumio[671]: info: Oct 12 13:01:53 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:53 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:53 volumio volumio[671]: info: sendMpdCommand status took 49 milliseconds Oct 12 13:01:53 volumio volumio[671]: info: sendMpdCommand status took 37 milliseconds Oct 12 13:01:53 volumio volumio[671]: info: sendMpdCommand status took 27 milliseconds Oct 12 13:01:53 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:01:53 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:01:53 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:01:53 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 12 13:01:53 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::syncState stateService stop Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus stop Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: No code Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 12 13:01:53 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::syncState stateService stop Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus stop Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: No code Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Oct 12 13:01:53 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::syncState stateService stop Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus stop Oct 12 13:01:53 volumio go-librespot[27850]: time="2024-10-12T13:01:53+02:00" level=debug msg="completed challenge" Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio volumio[671]: info: No code Oct 12 13:01:53 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:01:53 volumio go-librespot[27850]: time="2024-10-12T13:01:53+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:01:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:53 volumio volumio[671]: info: ------------------------------ 600ms Oct 12 13:01:53 volumio volumio[671]: info: ------------------------------ 589ms Oct 12 13:01:53 volumio volumio[671]: info: ------------------------------ 583ms Oct 12 13:01:53 volumio volumio[671]: info: Oct 12 13:01:53 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:53 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:53 volumio volumio[671]: info: Oct 12 13:01:53 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:53 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:53 volumio volumio[671]: error: updateQueue error: null Oct 12 13:01:53 volumio volumio[671]: error: updateQueue error: null Oct 12 13:01:53 volumio volumio[671]: error: updateQueue error: null Oct 12 13:01:53 volumio volumio[671]: info: ------------------------------ 605ms Oct 12 13:01:53 volumio volumio[671]: info: ------------------------------ 36ms Oct 12 13:01:53 volumio volumio[671]: info: ------------------------------ 29ms Oct 12 13:01:53 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:53 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:53 volumio volumio[671]: info: Connection to go-librespot Websocket closed Oct 12 13:01:54 volumio volumio[671]: info: Starting UPNP Playback Oct 12 13:01:54 volumio volumio[671]: info: Preparing playback through UPNP Oct 12 13:01:54 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:54 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:01:54 volumio volumio[671]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 37ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 25ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 18ms Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 35ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 26ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 18ms Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 38ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 29ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 21ms Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 36ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 26ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 19ms Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 38ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 28ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 22ms Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: Oct 12 13:01:54 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:54 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 35ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 26ms Oct 12 13:01:54 volumio volumio[671]: info: ------------------------------ 19ms Oct 12 13:01:55 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:01:55 volumio volumio[671]: (node:671) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:55 volumio volumio[671]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Oct 12 13:01:55 volumio volumio[671]: (node:671) 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: 38036) Oct 12 13:01:55 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:01:55 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:01:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57634. Oct 12 13:01:56 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:01:56 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:01:56 volumio go-librespot[27885]: Librespot-go daemon starting... Oct 12 13:01:56 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:56 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:01:56 volumio go-librespot[27885]: time="2024-10-12T13:01:56+02:00" level=info msg="generated new device id: a06efe2df3cde6fdb3dbb94c3640fc94a5613429" Oct 12 13:01:56 volumio go-librespot[27885]: time="2024-10-12T13:01:56+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:01:58 volumio volumio[671]: info: Starting UPNP Playback Oct 12 13:01:58 volumio volumio[671]: info: Preparing playback through UPNP Oct 12 13:01:58 volumio volumio[671]: info: Consume mode Oct 12 13:01:58 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:01:58 volumio volumio[671]: info: CoreCommandRouter::volumioStop Oct 12 13:01:58 volumio volumio[671]: info: CoreStateMachine::stop Oct 12 13:01:58 volumio volumio[671]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 12 13:01:58 volumio volumio[671]: info: CoreStateMachine::setConsumeUpdateService mpd Oct 12 13:01:58 volumio go-librespot[27885]: time="2024-10-12T13:01:58+02:00" level=debug msg="obtained new client token: AACJB9icSDTY+NBS6svx9aOAOA4FDV7TVG6K6dk/J9zDca8dFVX/uEyH25G/CbKUumWBOkwApRfVfqNCh41+xq4ocEIDGVXjwqR95OPNLrooht6kWQENsOiHPRqhv0aNCzLwGdQpsjOK/3oJKb6HaWNVKnwiVq63OxrKfTvykbxV+FjSEhfmCK+dJ0DOhXlejpGB+PA9hm4jZm07VROnuCMrXW6fuiR0SnO8+Kbbp/T4XxkFKRfwY2Ljjou+w1UyQQ==" Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 58ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 55ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 40ms Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 60ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 48ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 31ms Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 54ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 55ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 37ms Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 84ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 61ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 45ms Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 67ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 47ms Oct 12 13:01:58 volumio volumio[671]: info: ------------------------------ 36ms Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:58 volumio volumio[671]: info: Oct 12 13:01:58 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:58 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:59 volumio volumio[671]: info: Oct 12 13:01:59 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:01:59 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:01:59 volumio volumio[671]: info: ------------------------------ 37ms Oct 12 13:01:59 volumio volumio[671]: info: ------------------------------ 32ms Oct 12 13:01:59 volumio volumio[671]: info: ------------------------------ 24ms Oct 12 13:01:59 volumio go-librespot[27885]: time="2024-10-12T13:01:59+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Oct 12 13:01:59 volumio go-librespot[27885]: time="2024-10-12T13:01:59+02:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Oct 12 13:01:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:01:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:01:59 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:01:59 volumio volumio[671]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Oct 12 13:02:00 volumio volumio[671]: info: Oct 12 13:02:00 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:00 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:00 volumio volumio[671]: info: Oct 12 13:02:00 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:00 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:00 volumio volumio[671]: info: Oct 12 13:02:00 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:00 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:00 volumio volumio[671]: info: Oct 12 13:02:00 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:00 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand status took 104 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand status took 86 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand status took 76 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand status took 67 milliseconds Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:00 volumio volumio[671]: info: Oct 12 13:02:00 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:00 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:00 volumio volumio[671]: info: Oct 12 13:02:00 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:00 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:00 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand playlistinfo took 73 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand playlistinfo took 72 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand playlistinfo took 64 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand playlistinfo took 67 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand status took 46 milliseconds Oct 12 13:02:00 volumio volumio[671]: info: sendMpdCommand status took 35 milliseconds Oct 12 13:02:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:02:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57635. Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:02 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:02 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:02 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:02 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:02 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tańczyć chcę (Radio Edit)","artist":"Long & Junior","album":"Tańczyć chcę (Radio Edit)","uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:02 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus stop Oct 12 13:02:02 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:02 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:02 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tańczyć chcę (Radio Edit)","artist":"Long & Junior","album":"Tańczyć chcę (Radio Edit)","uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:02 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:02 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 12 13:02:02 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:02:02 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:02 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:02 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tańczyć chcę (Radio Edit)","artist":"Long & Junior","album":"Tańczyć chcę (Radio Edit)","uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:02 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:02 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:02:02 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:02 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:02:02 volumio go-librespot[27908]: Librespot-go daemon starting... Oct 12 13:02:03 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:03 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:03 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Tańczyć chcę (Radio Edit)","artist":"Long & Junior","album":"Tańczyć chcę (Radio Edit)","uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:03 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:03 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::volumioPushState Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 2509ms Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 2670ms Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 2670ms Oct 12 13:02:03 volumio go-librespot[27908]: time="2024-10-12T13:02:03+02:00" level=info msg="generated new device id: 57870bbb86c3fc737163d9b963d8e18b15573c2e" Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 2675ms Oct 12 13:02:03 volumio go-librespot[27908]: time="2024-10-12T13:02:03+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:02:03 volumio volumio[671]: info: Initializing connection to go-librespot Websocket Oct 12 13:02:03 volumio volumio[671]: info: Oct 12 13:02:03 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:02:03 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:02:03 volumio volumio[671]: info: Oct 12 13:02:03 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:03 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand playlistinfo took 689 milliseconds Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand playlistinfo took 687 milliseconds Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:03 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:03 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:03 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","artist":"Long & Junior - Tańczyć chcę (Radio Edit)","album":null,"uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:03 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:03 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:03 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:02:03 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:03 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:03 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","artist":"Long & Junior - Tańczyć chcę (Radio Edit)","album":null,"uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:03 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:03 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:03 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:03 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:03 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:02:03 volumio volumio[671]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 12 13:02:03 volumio volumio[671]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 2841ms Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 2830ms Oct 12 13:02:03 volumio volumio[671]: info: Oct 12 13:02:03 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:02:03 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:02:03 volumio volumio[671]: info: Oct 12 13:02:03 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:03 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:03 volumio volumio[671]: info: Oct 12 13:02:03 volumio volumio[671]: ---------------------------- MPD announces system playlist update Oct 12 13:02:03 volumio volumio[671]: info: Ignoring MPD Status Update Oct 12 13:02:03 volumio volumio[671]: info: Oct 12 13:02:03 volumio volumio[671]: ---------------------------- MPD announces state update: player Oct 12 13:02:03 volumio volumio[671]: info: ControllerMpd::getState Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand status Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 491ms Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand status took 479 milliseconds Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 247ms Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand status took 218 milliseconds Oct 12 13:02:03 volumio volumio[671]: info: ------------------------------ 212ms Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand status took 186 milliseconds Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::parseState Oct 12 13:02:03 volumio volumio[671]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand playlistinfo took 66 milliseconds Oct 12 13:02:03 volumio go-librespot[27908]: time="2024-10-12T13:02:03+02:00" level=debug msg="new websocket client" Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand playlistinfo took 60 milliseconds Oct 12 13:02:03 volumio volumio[671]: info: sendMpdCommand playlistinfo took 66 milliseconds Oct 12 13:02:04 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:04 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:04 volumio volumio[671]: verbose: ControllerMpd::parseTrackInfo Oct 12 13:02:04 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:04 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:04 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:04 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1601,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"931 Kbps","isStreaming":false,"title":"17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","artist":"Long & Junior - Tańczyć chcę (Radio Edit)","album":null,"uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:04 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:04 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:04 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:04 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:02:04 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:04 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:04 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:04 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1830,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"847 Kbps","isStreaming":false,"title":"17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","artist":"Long & Junior - Tańczyć chcę (Radio Edit)","album":null,"uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:04 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:04 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:04 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:04 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:02:04 volumio volumio[671]: info: ControllerMpd::pushState Oct 12 13:02:04 volumio volumio[671]: info: CoreCommandRouter::servicePushState Oct 12 13:02:04 volumio volumio[671]: verbose: In UPNP mode Oct 12 13:02:04 volumio volumio[671]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1967,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"957 Kbps","isStreaming":false,"title":"17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","artist":"Long & Junior - Tańczyć chcę (Radio Edit)","album":null,"uri":"http://192.168.1.155:8097/single/uuid:548a2cb5-2925-37ea-1818-b827eb2bf7d2/17d85956ff4445cfac49fd4ca2d925ea.flac?ts=1728730911","trackType":""} Oct 12 13:02:04 volumio volumio[671]: verbose: CURRENT POSITION 0 Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::syncState stateService play Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::syncState currentStatus play Oct 12 13:02:04 volumio volumio[671]: info: Received an update from plugin. extracting info from payload Oct 12 13:02:04 volumio volumio[671]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Oct 12 13:02:04 volumio volumio[671]: info: CoreStateMachine::pushState Oct 12 13:02:04 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:02:04 volumio volumio[671]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 12 13:02:04 volumio volumio[671]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 12 13:02:04 volumio volumio[671]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Oct 12 13:02:04 volumio volumio[671]: info: ------------------------------ 853ms Oct 12 13:02:04 volumio volumio[671]: info: ------------------------------ 599ms Oct 12 13:02:04 volumio volumio[671]: info: ------------------------------ 564ms Oct 12 13:02:04 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:02:04 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:02:04 volumio volumio[671]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Oct 12 13:02:04 volumio volumio[671]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 12 13:02:04 volumio volumio[671]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Oct 12 13:02:04 volumio volumio[671]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Oct 12 13:02:04 volumio volumio[671]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 12 13:02:04 volumio volumio[671]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Oct 12 13:02:04 volumio volumio[671]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Oct 12 13:02:04 volumio volumio[671]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 12 13:02:04 volumio volumio[671]: at /volumio/node_modules/express/lib/router/index.js:281:22 Oct 12 13:02:04 volumio volumio[671]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 12 13:02:04 volumio volumio[671]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 12 13:02:04 volumio volumio[671]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Oct 12 13:02:04 volumio volumio[671]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Oct 12 13:02:04 volumio volumio[671]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Oct 12 13:02:04 volumio volumio[671]: at /volumio/node_modules/express/lib/router/index.js:284:7 Oct 12 13:02:04 volumio volumio[671]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Oct 12 13:02:04 volumio volumio[671]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Oct 12 13:02:04 volumio volumio[671]: info: Connection to go-librespot Websocket established Oct 12 13:02:04 volumio volumio[671]: info: Listing playlists Oct 12 13:02:04 volumio volumio[671]: info: Listing playlists Oct 12 13:02:06 volumio go-librespot[27908]: time="2024-10-12T13:02:06+02:00" level=debug msg="obtained new client token: AADapIfsMhzslcO2GSRCYrwyIZ1HAW/VC/3FbiTb7qoOwO7aTEWdjq0iqUuDfI4ilA/J/L16oT4S3WNkyluPNAmXbZibCk0xHoqXgX4wghnxfRKSutr9FgOYtus3SAkG00HjpJ8ccA+bztTvCGgqqbJeHGP99+n7ATIknU/LTWRUCk7Pw3h0N8ter0tWx68BG0al6yYviRJmNk2GiuBg9hXi97n/jYkl1h7I2QrbZB/tJJEbkFeP1hN0pyGakgmI6A==" Oct 12 13:02:06 volumio go-librespot[27908]: time="2024-10-12T13:02:06+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Oct 12 13:02:07 volumio go-librespot[27908]: time="2024-10-12T13:02:07+02:00" level=debug msg="completed keyexchange" Oct 12 13:02:07 volumio volumio[671]: info: Getting Spotify volume Oct 12 13:02:07 volumio volumio[671]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Oct 12 13:02:07 volumio volumio[671]: info: CoreCommandRouter::volumioGetState Oct 12 13:02:07 volumio volumio[671]: info: CorePlayQueue::getTrack 0 Oct 12 13:02:07 volumio volumio[671]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 12 13:02:07 volumio volumio[671]: TypeError: Cannot read property 'name' of undefined Oct 12 13:02:07 volumio volumio[671]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Oct 12 13:02:07 volumio volumio[671]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Oct 12 13:02:07 volumio volumio[671]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Oct 12 13:02:07 volumio volumio[671]: at Socket.emit (events.js:315:20) Oct 12 13:02:07 volumio volumio[671]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Oct 12 13:02:07 volumio volumio[671]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Oct 12 13:02:07 volumio volumio[671]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 12 13:02:07 volumio go-librespot[27908]: time="2024-10-12T13:02:07+02:00" level=debug msg="completed challenge" Oct 12 13:02:07 volumio go-librespot[27908]: time="2024-10-12T13:02:07+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Oct 12 13:02:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Oct 12 13:02:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Oct 12 13:02:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Oct 12 13:02:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 57636. Oct 12 13:02:11 volumio systemd[1]: Stopped go-librespot Daemon. Oct 12 13:02:11 volumio systemd[1]: Started go-librespot Daemon. Oct 12 13:02:11 volumio go-librespot[27943]: Librespot-go daemon starting... Oct 12 13:02:11 volumio go-librespot[27943]: time="2024-10-12T13:02:11+02:00" level=info msg="generated new device id: 45d99f3f175f5fe088c978f9ef60c2ba9b180dbb" Oct 12 13:02:11 volumio go-librespot[27943]: time="2024-10-12T13:02:11+02:00" level=debug msg="stored credentials found for 21wrcryivf656r7c4ma5g6giq" Oct 12 13:02:14 volumio sudo[27963]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-12 13:01 Oct 12 13:02:14 volumio sudo[27963]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 12 13:02:14 volumio go-librespot[27943]: time="2024-10-12T13:02:14+02:00" level=debug msg="obtained new client token: AAAmDNBCHNN1qFdEzXoDbiB4Jr/7M59P+CbLwcIVduP9dHlVy1CJcq3D/kK16hcS4OE6gafMdPw65Zap2pfk5JJyroVr6ygtOWgAq8yF+pHq5BClFh3QX39PDIWxLA8OQ5DXuOCFZdpFQDmD3AHj3jxdW7WZBRXYoowszyHAwPkZLrtzxxBZrqJcwun8qnxtYCxZZ0fqBwwtoZfyWk/sEBzkhZd6BW9Zu93Ndf7Cev2DLAlkRXSm8XX6wyvgJko=" Oct 12 13:02:14 volumio go-librespot[27943]: time="2024-10-12T13:02:14+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"