-- Logs begin at Sun 2024-07-07 23:02:10 CST, end at Thu 2024-07-11 09:57:42 CST. -- Jul 11 09:56:00 volumio go-librespot[2702]: time="2024-07-11T09:56:00+08:00" level=debug msg="obtained new client token: AACoN2i9A0Zc840CLDhMt+l4bi1bsXC9UuOajrxixD/4QbWaTc2M+OoS78loNsRufpjn6M0NyXi660rJe0o7RVcyyv/FjtEjfQEYO+e04ZG2QzqnMR/IP5n+LGVu8X6bnbjnYUc9jkyuewqbbm9Bm+AhRy/VRpUi/STtARAqtCMyilFBc15ucSFeaAb7wCFDgkzPfQ+GGB5CSgg/b1bXnvVWvLEncAiUOao49ZLa14UBiIewxcu5TBD2Yx4dJ0UJPg==" Jul 11 09:56:01 volumio go-librespot[2702]: time="2024-07-11T09:56:01+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 11 09:56:02 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:02 volumio go-librespot[2702]: time="2024-07-11T09:56:02+08:00" level=debug msg="new websocket client" Jul 11 09:56:02 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:56:04 volumio go-librespot[2702]: time="2024-07-11T09:56:04+08:00" level=debug msg="completed keyexchange" Jul 11 09:56:04 volumio go-librespot[2702]: time="2024-07-11T09:56:04+08:00" level=debug msg="completed challenge" Jul 11 09:56:05 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:56:05 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:56:05 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:05 volumio volumio[882]: info: Jul 11 09:56:05 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:05 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:05 volumio volumio[882]: info: Jul 11 09:56:05 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:05 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:05 volumio volumio[882]: info: Jul 11 09:56:05 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:05 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:05 volumio volumio[882]: info: Jul 11 09:56:05 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:05 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:05 volumio volumio[882]: info: Jul 11 09:56:05 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:05 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:05 volumio volumio[882]: info: Jul 11 09:56:05 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:05 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:05 volumio volumio[882]: info: ------------------------------ 17ms Jul 11 09:56:05 volumio volumio[882]: info: sendMpdCommand status took 15 milliseconds Jul 11 09:56:05 volumio volumio[882]: info: ------------------------------ 15ms Jul 11 09:56:05 volumio volumio[882]: info: sendMpdCommand status took 11 milliseconds Jul 11 09:56:05 volumio volumio[882]: info: ------------------------------ 10ms Jul 11 09:56:05 volumio volumio[882]: info: sendMpdCommand status took 3 milliseconds Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:05 volumio volumio[882]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 11 09:56:05 volumio volumio[882]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 11 09:56:05 volumio volumio[882]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:05 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:05 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:05 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:05 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":60724,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:05 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:05 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:05 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:05 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:05 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":60724,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:05 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:05 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:05 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:05 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:05 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":60724,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:05 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:05 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:05 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:05 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:05 volumio volumio[882]: info: ------------------------------ 168ms Jul 11 09:56:05 volumio volumio[882]: info: ------------------------------ 165ms Jul 11 09:56:05 volumio volumio[882]: info: ------------------------------ 159ms Jul 11 09:56:05 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:05 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:05 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:05 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:05 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:05 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:07 volumio go-librespot[2702]: time="2024-07-11T09:56:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:56:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:56:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:56:07 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 11 09:56:07 volumio volumio[882]: at connResetException (internal/errors.js:607:14) Jul 11 09:56:07 volumio volumio[882]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 11 09:56:07 volumio volumio[882]: at Socket.emit (events.js:327:22) Jul 11 09:56:07 volumio volumio[882]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 11 09:56:07 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 11 09:56:07 volumio volumio[882]: (node:882) 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: 44) Jul 11 09:56:07 volumio volumio[882]: info: Connection to go-librespot Websocket closed Jul 11 09:56:10 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:10 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:56:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 35. Jul 11 09:56:10 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:56:10 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:56:10 volumio go-librespot[2740]: Librespot-go daemon starting... Jul 11 09:56:10 volumio go-librespot[2740]: time="2024-07-11T09:56:10+08:00" level=info msg="generated new device id: cd3642b474fd2d37cac98de530bb9891972e7365" Jul 11 09:56:10 volumio go-librespot[2740]: time="2024-07-11T09:56:10+08:00" level=debug msg="stored credentials not found" Jul 11 09:56:13 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:13 volumio go-librespot[2740]: time="2024-07-11T09:56:13+08:00" level=debug msg="new websocket client" Jul 11 09:56:13 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:56:16 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:56:16 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:56:16 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:56:16 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:16 volumio go-librespot[2740]: time="2024-07-11T09:56:16+08:00" level=debug msg="obtained new client token: AABGecFg5yEPY46KH7nJM/bmcdeXfDlVtQwkh0TFofjHsZ9zxTIij8xIT1NGxlV6Jdy1xHvdj/oFIE+rE5BuPQkKHZfd/56PosLID6VFqdvTlR9k9rM0MAtTC4WKhNSLlex0kNzFGw26HNOizm8uz8kKfFYDtws+VCYu6aKc8LsACumCwK+Et8uaZP041YcCzETq8snVUeN89Q7UJujjfcSOlc9MaJNE0ItjV2ZY4qk8nl6dKAmuY1hBtaUdViks2A==" Jul 11 09:56:20 volumio volumio[882]: info: Jul 11 09:56:20 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:20 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:20 volumio volumio[882]: info: Jul 11 09:56:20 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:20 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:20 volumio volumio[882]: info: Jul 11 09:56:20 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:20 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:20 volumio volumio[882]: info: Jul 11 09:56:20 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:20 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:20 volumio volumio[882]: info: Jul 11 09:56:20 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:20 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:20 volumio volumio[882]: info: Jul 11 09:56:20 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:20 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:20 volumio volumio[882]: info: ------------------------------ 13ms Jul 11 09:56:20 volumio volumio[882]: info: sendMpdCommand status took 11 milliseconds Jul 11 09:56:20 volumio volumio[882]: info: ------------------------------ 9ms Jul 11 09:56:20 volumio volumio[882]: info: sendMpdCommand status took 8 milliseconds Jul 11 09:56:20 volumio volumio[882]: info: ------------------------------ 7ms Jul 11 09:56:20 volumio volumio[882]: info: sendMpdCommand status took 6 milliseconds Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:20 volumio volumio[882]: info: sendMpdCommand playlistinfo took 13 milliseconds Jul 11 09:56:20 volumio volumio[882]: info: sendMpdCommand playlistinfo took 13 milliseconds Jul 11 09:56:20 volumio volumio[882]: info: sendMpdCommand playlistinfo took 13 milliseconds Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:20 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:20 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:20 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:20 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":75866,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:20 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:20 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:20 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:20 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:20 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":75866,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:20 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:20 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:20 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:20 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:20 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":75866,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:20 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:20 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:20 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:20 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:20 volumio volumio[882]: info: ------------------------------ 165ms Jul 11 09:56:20 volumio volumio[882]: info: ------------------------------ 161ms Jul 11 09:56:20 volumio volumio[882]: info: ------------------------------ 160ms Jul 11 09:56:20 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:20 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:20 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:20 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:20 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:20 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:27 volumio go-librespot[2740]: time="2024-07-11T09:56:27+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 11 09:56:28 volumio go-librespot[2740]: time="2024-07-11T09:56:28+08:00" level=debug msg="completed keyexchange" Jul 11 09:56:28 volumio go-librespot[2740]: time="2024-07-11T09:56:28+08:00" level=debug msg="completed challenge" Jul 11 09:56:29 volumio go-librespot[2740]: time="2024-07-11T09:56:29+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:56:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:56:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:56:29 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 11 09:56:29 volumio volumio[882]: at connResetException (internal/errors.js:607:14) Jul 11 09:56:29 volumio volumio[882]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 11 09:56:29 volumio volumio[882]: at Socket.emit (events.js:327:22) Jul 11 09:56:29 volumio volumio[882]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 11 09:56:29 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 11 09:56:29 volumio volumio[882]: (node:882) 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: 45) Jul 11 09:56:29 volumio volumio[882]: info: Connection to go-librespot Websocket closed Jul 11 09:56:30 volumio volumio[882]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Jul 11 09:56:30 volumio volumio[882]: LoungeScreenDisconnected { Jul 11 09:56:30 volumio volumio[882]: AID: null, Jul 11 09:56:30 volumio volumio[882]: name: 'loungeScreenDisconnected', Jul 11 09:56:30 volumio volumio[882]: payload: {} Jul 11 09:56:30 volumio volumio[882]: } Jul 11 09:56:30 volumio volumio[882]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Jul 11 09:56:30 volumio volumio[882]: Stack trace: Jul 11 09:56:30 volumio volumio[882]: IncompleteAPIDataError: Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Jul 11 09:56:30 volumio volumio[882]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Jul 11 09:56:30 volumio volumio[882]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Jul 11 09:56:30 volumio volumio[882]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Jul 11 09:56:30 volumio volumio[882]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Jul 11 09:56:30 volumio volumio[882]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) 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: 47) Jul 11 09:56:30 volumio volumio[882]: error: [yt-cast-receiver] (YouTube) Error occurred in SendMessageTask: Jul 11 09:56:30 volumio volumio[882]: LoungeScreenDisconnected { Jul 11 09:56:30 volumio volumio[882]: AID: null, Jul 11 09:56:30 volumio volumio[882]: name: 'loungeScreenDisconnected', Jul 11 09:56:30 volumio volumio[882]: payload: {} Jul 11 09:56:30 volumio volumio[882]: } Jul 11 09:56:30 volumio volumio[882]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Jul 11 09:56:30 volumio volumio[882]: Stack trace: Jul 11 09:56:30 volumio volumio[882]: IncompleteAPIDataError: Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Jul 11 09:56:30 volumio volumio[882]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Jul 11 09:56:30 volumio volumio[882]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Jul 11 09:56:30 volumio volumio[882]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Jul 11 09:56:30 volumio volumio[882]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Jul 11 09:56:30 volumio volumio[882]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) 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: 49) Jul 11 09:56:30 volumio volumio[882]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Jul 11 09:56:30 volumio volumio[882]: LoungeScreenDisconnected { Jul 11 09:56:30 volumio volumio[882]: AID: null, Jul 11 09:56:30 volumio volumio[882]: name: 'loungeScreenDisconnected', Jul 11 09:56:30 volumio volumio[882]: payload: {} Jul 11 09:56:30 volumio volumio[882]: } Jul 11 09:56:30 volumio volumio[882]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Jul 11 09:56:30 volumio volumio[882]: Stack trace: Jul 11 09:56:30 volumio volumio[882]: IncompleteAPIDataError: Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Jul 11 09:56:30 volumio volumio[882]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Jul 11 09:56:30 volumio volumio[882]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Jul 11 09:56:30 volumio volumio[882]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Jul 11 09:56:30 volumio volumio[882]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Jul 11 09:56:30 volumio volumio[882]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) 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: 51) Jul 11 09:56:30 volumio volumio[882]: error: [yt-cast-receiver] (YouTube) Error occurred in SendMessageTask: Jul 11 09:56:30 volumio volumio[882]: LoungeScreenDisconnected { Jul 11 09:56:30 volumio volumio[882]: AID: null, Jul 11 09:56:30 volumio volumio[882]: name: 'loungeScreenDisconnected', Jul 11 09:56:30 volumio volumio[882]: payload: {} Jul 11 09:56:30 volumio volumio[882]: } Jul 11 09:56:30 volumio volumio[882]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Jul 11 09:56:30 volumio volumio[882]: Stack trace: Jul 11 09:56:30 volumio volumio[882]: IncompleteAPIDataError: Missing data required to construct query string from bind params Jul 11 09:56:30 volumio volumio[882]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Jul 11 09:56:30 volumio volumio[882]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Jul 11 09:56:30 volumio volumio[882]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Jul 11 09:56:30 volumio volumio[882]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Jul 11 09:56:30 volumio volumio[882]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Jul 11 09:56:30 volumio volumio[882]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Jul 11 09:56:30 volumio volumio[882]: at runMicrotasks () Jul 11 09:56:30 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Jul 11 09:56:30 volumio volumio[882]: (node:882) 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: 53) Jul 11 09:56:32 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:32 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:56:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 36. Jul 11 09:56:32 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:56:32 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:56:32 volumio go-librespot[2816]: Librespot-go daemon starting... Jul 11 09:56:32 volumio go-librespot[2816]: time="2024-07-11T09:56:32+08:00" level=info msg="generated new device id: 5a9afa8405634ea549b5e9ae4ee42fca900b3a8c" Jul 11 09:56:32 volumio go-librespot[2816]: time="2024-07-11T09:56:32+08:00" level=debug msg="stored credentials not found" Jul 11 09:56:33 volumio go-librespot[2816]: time="2024-07-11T09:56:33+08:00" level=debug msg="obtained new client token: AABOeBw/dGyaKVSXj1Ga/vjxF5l0FFQNCJ84gAqXHijjtB9vfoWVClN87i/HKZcoApf2tDXVPq9fVolyMm33kPVedMTx7UwqR6P20bDanePabCdXg380PezQfC1A/n1evJTOQpIKFaY/8qqQQMqrSwE9u/N5jHUwljR/QezZ4EK06Wcc8CvVt6kAhdJlJp6Mjt7tDvzgllyb0OHvX7kpgp7Wfih+76WfvzS4beSH7UVAeIfvFYV42x3otxpQ2YU=" Jul 11 09:56:35 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:35 volumio go-librespot[2816]: time="2024-07-11T09:56:35+08:00" level=debug msg="new websocket client" Jul 11 09:56:35 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:56:36 volumio volumio[882]: info: Jul 11 09:56:36 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:36 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:36 volumio volumio[882]: info: Jul 11 09:56:36 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:36 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:36 volumio volumio[882]: info: Jul 11 09:56:36 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:36 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:36 volumio volumio[882]: info: Jul 11 09:56:36 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:36 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:36 volumio volumio[882]: info: Jul 11 09:56:36 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:36 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:36 volumio volumio[882]: info: Jul 11 09:56:36 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:36 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:36 volumio volumio[882]: info: ------------------------------ 12ms Jul 11 09:56:36 volumio volumio[882]: info: sendMpdCommand status took 10 milliseconds Jul 11 09:56:36 volumio go-librespot[2816]: time="2024-07-11T09:56:36+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 11 09:56:36 volumio volumio[882]: info: ------------------------------ 9ms Jul 11 09:56:36 volumio volumio[882]: info: sendMpdCommand status took 7 milliseconds Jul 11 09:56:36 volumio volumio[882]: info: ------------------------------ 9ms Jul 11 09:56:36 volumio volumio[882]: info: sendMpdCommand status took 6 milliseconds Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:36 volumio volumio[882]: info: sendMpdCommand playlistinfo took 3 milliseconds Jul 11 09:56:36 volumio volumio[882]: info: sendMpdCommand playlistinfo took 3 milliseconds Jul 11 09:56:36 volumio volumio[882]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:36 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:36 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:36 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:36 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":91379,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"160 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:36 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:36 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:36 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:36 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:36 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":91379,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"160 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:36 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:36 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:36 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:36 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:36 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":91379,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"160 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:36 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:36 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:36 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:36 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:36 volumio volumio[882]: info: ------------------------------ 165ms Jul 11 09:56:36 volumio volumio[882]: info: ------------------------------ 160ms Jul 11 09:56:36 volumio volumio[882]: info: ------------------------------ 159ms Jul 11 09:56:36 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:36 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:36 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:36 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:36 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:36 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:37 volumio go-librespot[2816]: time="2024-07-11T09:56:37+08:00" level=debug msg="completed keyexchange" Jul 11 09:56:37 volumio go-librespot[2816]: time="2024-07-11T09:56:37+08:00" level=debug msg="completed challenge" Jul 11 09:56:37 volumio go-librespot[2816]: time="2024-07-11T09:56:37+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:56:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:56:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:56:37 volumio volumio[882]: info: Connection to go-librespot Websocket closed Jul 11 09:56:38 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:56:38 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:38 volumio volumio[882]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 11 09:56:38 volumio volumio[882]: (node:882) 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: 54) Jul 11 09:56:38 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:56:38 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:56:38 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:40 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:40 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:40 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:56:40 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 37. Jul 11 09:56:40 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:56:41 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:56:41 volumio go-librespot[2890]: Librespot-go daemon starting... Jul 11 09:56:41 volumio go-librespot[2890]: time="2024-07-11T09:56:41+08:00" level=info msg="generated new device id: d4e8205af1cacc91315dfd4b6216c145c381673f" Jul 11 09:56:41 volumio go-librespot[2890]: time="2024-07-11T09:56:41+08:00" level=debug msg="stored credentials not found" Jul 11 09:56:42 volumio go-librespot[2890]: time="2024-07-11T09:56:42+08:00" level=debug msg="obtained new client token: AADwtrEbzgHt/WUJ16+AdpClC2UAG68b2l7WvLfS+zVklHY79vA6lIafHvxU+Zq9MTs7q1SG9XdVfWkiLRf0P1O6HcrXWNNKparQxhvpe6hfCX/ouWX1wHLnONyfiAevwmBUGv6+nOfxXCDG8aPrRoKmv5JDbbya6PdLZnI1A24lDRYD4S+HmaK4w0JE1YYFXeMIbVg+J+T37FlcMF9nQUrQK13DeXHKymxmubHTd8b/1ph4JmiOHLJoQpkGLEEGiA==" Jul 11 09:56:43 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:43 volumio go-librespot[2890]: time="2024-07-11T09:56:43+08:00" level=debug msg="new websocket client" Jul 11 09:56:43 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:56:44 volumio go-librespot[2890]: time="2024-07-11T09:56:44+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 11 09:56:44 volumio go-librespot[2890]: time="2024-07-11T09:56:44+08:00" level=debug msg="completed keyexchange" Jul 11 09:56:44 volumio go-librespot[2890]: time="2024-07-11T09:56:44+08:00" level=debug msg="completed challenge" Jul 11 09:56:45 volumio go-librespot[2890]: time="2024-07-11T09:56:45+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:56:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:56:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:56:45 volumio volumio[882]: info: Connection to go-librespot Websocket closed Jul 11 09:56:46 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:56:46 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:46 volumio volumio[882]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 11 09:56:46 volumio volumio[882]: (node:882) 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: 55) Jul 11 09:56:46 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:56:46 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:56:46 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:48 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:48 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:56:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 38. Jul 11 09:56:48 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:56:48 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:56:48 volumio go-librespot[2913]: Librespot-go daemon starting... Jul 11 09:56:48 volumio go-librespot[2913]: time="2024-07-11T09:56:48+08:00" level=info msg="generated new device id: 86002eece06069c9ca7f724439ee0e4466af35c4" Jul 11 09:56:48 volumio go-librespot[2913]: time="2024-07-11T09:56:48+08:00" level=debug msg="stored credentials not found" Jul 11 09:56:49 volumio go-librespot[2913]: time="2024-07-11T09:56:49+08:00" level=debug msg="obtained new client token: AACa9SpAmVngnPK891R32ThPWIeXRyBlc4MqhYHesDDc9c5XWnUI2eLkzzQcEc8e+yUIEtPW7aubnrrJjRCCFrdlRq6kjeinn9tdDp3wjauuFRm9loRkf9NbmSsCCneOaVmTnFN3xQsYARfctJEDLnsCUtkZIWn/TiQz9maLgPblgpYh2d78dTJ/FlIjxuzb8hcm1dy339oWDUaefxL2PXitee7Qb0pMBz10EfiH751lEuYgbPZb/Kk21ISqABs=" Jul 11 09:56:50 volumio go-librespot[2913]: time="2024-07-11T09:56:50+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 11 09:56:50 volumio go-librespot[2913]: time="2024-07-11T09:56:50+08:00" level=debug msg="completed keyexchange" Jul 11 09:56:50 volumio volumio[882]: info: Jul 11 09:56:50 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:50 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:50 volumio volumio[882]: info: Jul 11 09:56:50 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:50 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:50 volumio volumio[882]: info: Jul 11 09:56:50 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:50 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:50 volumio volumio[882]: info: Jul 11 09:56:50 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:50 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:50 volumio volumio[882]: info: Jul 11 09:56:50 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:56:50 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:56:50 volumio volumio[882]: info: Jul 11 09:56:50 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:56:50 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:56:50 volumio volumio[882]: info: ------------------------------ 14ms Jul 11 09:56:50 volumio volumio[882]: info: sendMpdCommand status took 6 milliseconds Jul 11 09:56:50 volumio volumio[882]: info: ------------------------------ 7ms Jul 11 09:56:50 volumio volumio[882]: info: sendMpdCommand status took 5 milliseconds Jul 11 09:56:50 volumio volumio[882]: info: ------------------------------ 4ms Jul 11 09:56:50 volumio volumio[882]: info: sendMpdCommand status took 4 milliseconds Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:56:50 volumio volumio[882]: info: sendMpdCommand playlistinfo took 5 milliseconds Jul 11 09:56:50 volumio volumio[882]: info: sendMpdCommand playlistinfo took 4 milliseconds Jul 11 09:56:50 volumio volumio[882]: info: sendMpdCommand playlistinfo took 3 milliseconds Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:50 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:56:50 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:50 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:50 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":106055,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:50 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:50 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:50 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:50 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:50 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":106055,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:50 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:50 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:50 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:56:50 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:56:50 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":106055,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:56:50 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:56:50 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:50 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:56:50 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:56:50 volumio volumio[882]: info: ------------------------------ 142ms Jul 11 09:56:50 volumio volumio[882]: info: ------------------------------ 140ms Jul 11 09:56:50 volumio volumio[882]: info: ------------------------------ 139ms Jul 11 09:56:50 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:50 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:50 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:50 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:50 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:50 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:51 volumio go-librespot[2913]: time="2024-07-11T09:56:51+08:00" level=debug msg="completed challenge" Jul 11 09:56:51 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:51 volumio go-librespot[2913]: time="2024-07-11T09:56:51+08:00" level=debug msg="new websocket client" Jul 11 09:56:51 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:56:51 volumio go-librespot[2913]: time="2024-07-11T09:56:51+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:56:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:56:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:56:51 volumio volumio[882]: info: Connection to go-librespot Websocket closed Jul 11 09:56:54 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:56:54 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:54 volumio volumio[882]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Jul 11 09:56:54 volumio volumio[882]: (node:882) 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: 56) Jul 11 09:56:54 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:56:54 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:56:54 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:56:54 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:54 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:56:54 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:56:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 39. Jul 11 09:56:54 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:56:54 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:56:54 volumio go-librespot[2943]: Librespot-go daemon starting... Jul 11 09:56:54 volumio go-librespot[2943]: time="2024-07-11T09:56:54+08:00" level=info msg="generated new device id: de93cd6cac7c2580af875af4cc66905dda3e5168" Jul 11 09:56:54 volumio go-librespot[2943]: time="2024-07-11T09:56:54+08:00" level=debug msg="stored credentials not found" Jul 11 09:56:55 volumio go-librespot[2943]: time="2024-07-11T09:56:55+08:00" level=debug msg="obtained new client token: AACHeabK274P1Ta+9HUeg6XbND69M3O4DnsgKrdfkCfGIJKzss3sy17E2EnAaSGiQgqPYYrAvL1rupdaoCtqzD9UlZzf747oq5iN8RuV08TcEJEdE0Q5yyc/ssMtooqZ83VltO6c77Z1u0xfxtMNWxYKC7ck9AUsyWlNqrTZbMiYzESKkHH44LIMqR9Z9LD3CBZs1XCC7yWaj/HVSd/REsvUtWLfajIRnBI8bjK15Ah5x7vARAC2iUSwo1M5F04/sA==" Jul 11 09:56:57 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:56:57 volumio go-librespot[2943]: time="2024-07-11T09:56:57+08:00" level=debug msg="new websocket client" Jul 11 09:56:57 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:57:00 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:57:00 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:57:00 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:57:00 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:01 volumio go-librespot[2943]: time="2024-07-11T09:57:01+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 11 09:57:07 volumio volumio[882]: info: Jul 11 09:57:07 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:07 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:07 volumio volumio[882]: info: Jul 11 09:57:07 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:07 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:07 volumio volumio[882]: info: Jul 11 09:57:07 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:07 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:07 volumio volumio[882]: info: Jul 11 09:57:07 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:07 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:07 volumio volumio[882]: info: Jul 11 09:57:07 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:07 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:07 volumio volumio[882]: info: Jul 11 09:57:07 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:07 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:07 volumio volumio[882]: info: ------------------------------ 12ms Jul 11 09:57:07 volumio volumio[882]: info: sendMpdCommand status took 10 milliseconds Jul 11 09:57:07 volumio volumio[882]: info: ------------------------------ 10ms Jul 11 09:57:07 volumio volumio[882]: info: sendMpdCommand status took 4 milliseconds Jul 11 09:57:07 volumio volumio[882]: info: ------------------------------ 3ms Jul 11 09:57:07 volumio volumio[882]: info: sendMpdCommand status took 3 milliseconds Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:07 volumio volumio[882]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 11 09:57:07 volumio volumio[882]: info: sendMpdCommand playlistinfo took 1 milliseconds Jul 11 09:57:07 volumio volumio[882]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:07 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:07 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:07 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:07 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":122862,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:07 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:07 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:07 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:07 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:07 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":122862,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:07 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:07 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:07 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:07 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:07 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":122862,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:07 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:07 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:07 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:07 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:07 volumio volumio[882]: info: ------------------------------ 148ms Jul 11 09:57:07 volumio volumio[882]: info: ------------------------------ 143ms Jul 11 09:57:07 volumio volumio[882]: info: ------------------------------ 140ms Jul 11 09:57:07 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:07 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:07 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:07 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:07 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:07 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:07 volumio go-librespot[2943]: time="2024-07-11T09:57:07+08:00" level=debug msg="completed keyexchange" Jul 11 09:57:08 volumio go-librespot[2943]: time="2024-07-11T09:57:08+08:00" level=debug msg="completed challenge" Jul 11 09:57:08 volumio go-librespot[2943]: time="2024-07-11T09:57:08+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:57:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:57:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:57:08 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 11 09:57:08 volumio volumio[882]: at connResetException (internal/errors.js:607:14) Jul 11 09:57:08 volumio volumio[882]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 11 09:57:08 volumio volumio[882]: at Socket.emit (events.js:327:22) Jul 11 09:57:08 volumio volumio[882]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 11 09:57:08 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 11 09:57:08 volumio volumio[882]: (node:882) 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: 57) Jul 11 09:57:08 volumio volumio[882]: info: Connection to go-librespot Websocket closed Jul 11 09:57:11 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:57:11 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:57:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:57:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 40. Jul 11 09:57:11 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:57:11 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:57:11 volumio go-librespot[2994]: Librespot-go daemon starting... Jul 11 09:57:11 volumio go-librespot[2994]: time="2024-07-11T09:57:11+08:00" level=info msg="generated new device id: 6cd747279cae9d4eaf7c529631e01620e688c9a4" Jul 11 09:57:11 volumio go-librespot[2994]: time="2024-07-11T09:57:11+08:00" level=debug msg="stored credentials not found" Jul 11 09:57:14 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:57:14 volumio go-librespot[2994]: time="2024-07-11T09:57:14+08:00" level=debug msg="new websocket client" Jul 11 09:57:14 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:57:17 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:57:17 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:57:17 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:57:17 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:22 volumio volumio[882]: info: Jul 11 09:57:22 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:22 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:22 volumio volumio[882]: info: Jul 11 09:57:22 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:22 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:22 volumio volumio[882]: info: Jul 11 09:57:22 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:22 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:22 volumio volumio[882]: info: Jul 11 09:57:22 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:22 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:22 volumio volumio[882]: info: Jul 11 09:57:22 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:22 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:22 volumio volumio[882]: info: Jul 11 09:57:22 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:22 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:22 volumio volumio[882]: info: ------------------------------ 8ms Jul 11 09:57:22 volumio volumio[882]: info: sendMpdCommand status took 4 milliseconds Jul 11 09:57:22 volumio volumio[882]: info: ------------------------------ 4ms Jul 11 09:57:22 volumio volumio[882]: info: sendMpdCommand status took 4 milliseconds Jul 11 09:57:22 volumio volumio[882]: info: ------------------------------ 3ms Jul 11 09:57:22 volumio volumio[882]: info: sendMpdCommand status took 2 milliseconds Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:22 volumio volumio[882]: info: sendMpdCommand playlistinfo took 4 milliseconds Jul 11 09:57:22 volumio volumio[882]: info: sendMpdCommand playlistinfo took 4 milliseconds Jul 11 09:57:22 volumio volumio[882]: info: sendMpdCommand playlistinfo took 3 milliseconds Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:22 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:22 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:22 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:22 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":137444,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:22 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:22 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:22 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:22 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:22 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":137444,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:22 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:22 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:22 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:22 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:22 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":137444,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:22 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:22 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:22 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:22 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:22 volumio volumio[882]: info: ------------------------------ 164ms Jul 11 09:57:22 volumio volumio[882]: info: ------------------------------ 165ms Jul 11 09:57:22 volumio volumio[882]: info: ------------------------------ 167ms Jul 11 09:57:22 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:22 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:22 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:22 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:22 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:22 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:22 volumio go-librespot[2994]: time="2024-07-11T09:57:22+08:00" level=debug msg="obtained new client token: AADt1BtIiPFtYPl4leKyay1C2/amjgmGr+picbEq4gfAPNtcUoKOMaWvuuW5ks9VACYro0eQUS4FmpGWTREMSDiDQ1AZQ0uLXjQQgTfyW2jHvbnycTydtbWku+GBe9zcp1epXIgb/DGaS0ejHOhl9U5jkg+SS69GRF5v7UWns7tITyk6qRZPDAESo91A57Qp6VnLisI+DV8x44KLdBkp9iVDd6UYl73qwzID/sVH+7SJFw9ssoSAyoVSTjR2wCHc4A==" Jul 11 09:57:28 volumio go-librespot[2994]: time="2024-07-11T09:57:28+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jul 11 09:57:28 volumio go-librespot[2994]: time="2024-07-11T09:57:28+08:00" level=debug msg="completed keyexchange" Jul 11 09:57:29 volumio go-librespot[2994]: time="2024-07-11T09:57:29+08:00" level=debug msg="completed challenge" Jul 11 09:57:29 volumio go-librespot[2994]: time="2024-07-11T09:57:29+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:57:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:57:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:57:29 volumio volumio[882]: (node:882) UnhandledPromiseRejectionWarning: Error: socket hang up Jul 11 09:57:29 volumio volumio[882]: at connResetException (internal/errors.js:607:14) Jul 11 09:57:29 volumio volumio[882]: at Socket.socketOnEnd (_http_client.js:493:23) Jul 11 09:57:29 volumio volumio[882]: at Socket.emit (events.js:327:22) Jul 11 09:57:29 volumio volumio[882]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 11 09:57:29 volumio volumio[882]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 11 09:57:29 volumio volumio[882]: (node:882) 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: 58) Jul 11 09:57:29 volumio volumio[882]: info: Connection to go-librespot Websocket closed Jul 11 09:57:32 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:57:32 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:57:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:57:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 41. Jul 11 09:57:32 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:57:32 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:57:32 volumio go-librespot[3053]: Librespot-go daemon starting... Jul 11 09:57:32 volumio go-librespot[3053]: time="2024-07-11T09:57:32+08:00" level=info msg="generated new device id: 031aa1f613058b0fd9b44c2a001f4e02c8420819" Jul 11 09:57:32 volumio go-librespot[3053]: time="2024-07-11T09:57:32+08:00" level=debug msg="stored credentials not found" Jul 11 09:57:33 volumio go-librespot[3053]: time="2024-07-11T09:57:33+08:00" level=debug msg="obtained new client token: AABZlFybj6DYr+QDRq7+j86PfFTKyxT56LQQtMyYGfAE5XpFVdnOLwEQxmVj2Y9nW/ws6WlVD19mEPKitLmAWfxYBOMr5B2GFVWkK7KYZQ0tB5jrsDw7qi7+uUmWhj98sxcxLeCrTiaPFD7wWRthAocy/qJeDmGioEGqvQz2tEKgog24ZXLDPAgY5270zMEHrsOwknpQnkVrZvBeoOBK6aB5jqAeO1keVyGZmJJvDNmZ0Gzd4YMfTbrqFGp3r3GMGA==" Jul 11 09:57:34 volumio go-librespot[3053]: time="2024-07-11T09:57:34+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 11 09:57:34 volumio go-librespot[3053]: time="2024-07-11T09:57:34+08:00" level=debug msg="completed keyexchange" Jul 11 09:57:34 volumio go-librespot[3053]: time="2024-07-11T09:57:34+08:00" level=debug msg="completed challenge" Jul 11 09:57:35 volumio go-librespot[3053]: time="2024-07-11T09:57:35+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Jul 11 09:57:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Jul 11 09:57:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Jul 11 09:57:35 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:57:35 volumio volumio[882]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Jul 11 09:57:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Jul 11 09:57:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 42. Jul 11 09:57:38 volumio systemd[1]: Stopped go-librespot Daemon. Jul 11 09:57:38 volumio systemd[1]: Started go-librespot Daemon. Jul 11 09:57:38 volumio go-librespot[3071]: Librespot-go daemon starting... Jul 11 09:57:38 volumio go-librespot[3071]: time="2024-07-11T09:57:38+08:00" level=info msg="generated new device id: 9606346ef88087509220d709be40adc010dcd207" Jul 11 09:57:38 volumio go-librespot[3071]: time="2024-07-11T09:57:38+08:00" level=debug msg="stored credentials not found" Jul 11 09:57:38 volumio volumio[882]: info: Initializing connection to go-librespot Websocket Jul 11 09:57:38 volumio go-librespot[3071]: time="2024-07-11T09:57:38+08:00" level=debug msg="new websocket client" Jul 11 09:57:38 volumio volumio[882]: info: Connection to go-librespot Websocket established Jul 11 09:57:39 volumio go-librespot[3071]: time="2024-07-11T09:57:39+08:00" level=debug msg="obtained new client token: AAAEwsuJQjw7ojHHEfhYCg0doecuDK1Q4T6vogusug/CFhKWDxeVYK4oenGXggqzDeQzMyFA6Mo4UgEMC2FB49KWQ0QXAYlzOkTnb/76A9xeuW11TubbNDUdMlV6v845qnuVOgFrOuyoUgg4h6LXSXHt1V7po6EXxHiTSV47JVm9m2jLR8gFXR0w1Snnx4G5VN/bqlvlC5hajvfdlaBXcghxty26b3fITxeTwIXQvblQMnn0rvstpgLfl5Ic7AvF0g==" Jul 11 09:57:39 volumio volumio[882]: info: Jul 11 09:57:39 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:39 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:39 volumio volumio[882]: info: Jul 11 09:57:39 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:39 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:39 volumio volumio[882]: info: Jul 11 09:57:39 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:39 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:39 volumio volumio[882]: info: Jul 11 09:57:39 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:39 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:39 volumio volumio[882]: info: Jul 11 09:57:39 volumio volumio[882]: ---------------------------- MPD announces system playlist update Jul 11 09:57:39 volumio volumio[882]: info: Ignoring MPD Status Update Jul 11 09:57:39 volumio volumio[882]: info: Jul 11 09:57:39 volumio volumio[882]: ---------------------------- MPD announces state update: player Jul 11 09:57:39 volumio volumio[882]: info: ControllerMpd::getState Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand status Jul 11 09:57:39 volumio volumio[882]: info: ------------------------------ 16ms Jul 11 09:57:39 volumio volumio[882]: info: sendMpdCommand status took 13 milliseconds Jul 11 09:57:39 volumio volumio[882]: info: ------------------------------ 13ms Jul 11 09:57:39 volumio volumio[882]: info: sendMpdCommand status took 12 milliseconds Jul 11 09:57:39 volumio volumio[882]: info: ------------------------------ 11ms Jul 11 09:57:39 volumio volumio[882]: info: sendMpdCommand status took 4 milliseconds Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::parseState Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jul 11 09:57:39 volumio volumio[882]: info: sendMpdCommand playlistinfo took 2 milliseconds Jul 11 09:57:39 volumio volumio[882]: info: sendMpdCommand playlistinfo took 1 milliseconds Jul 11 09:57:39 volumio volumio[882]: info: sendMpdCommand playlistinfo took 1 milliseconds Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:39 volumio volumio[882]: verbose: ControllerMpd::parseTrackInfo Jul 11 09:57:39 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:39 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:39 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":155097,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:39 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:39 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:39 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:39 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:39 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":155097,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:39 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:39 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:39 volumio volumio[882]: info: ControllerMpd::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::servicePushState Jul 11 09:57:39 volumio volumio[882]: info: CorePlayQueue::getTrack 0 Jul 11 09:57:39 volumio volumio[882]: verbose: STATE SERVICE {"status":"play","position":0,"seek":155097,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Tracklist: https://dancewave.online","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Jul 11 09:57:39 volumio volumio[882]: verbose: CURRENT POSITION 0 Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::syncState stateService play Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::syncState currentStatus play Jul 11 09:57:39 volumio volumio[882]: info: Received an update from plugin. extracting info from payload Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:39 volumio volumio[882]: info: CoreStateMachine::pushState Jul 11 09:57:39 volumio volumio[882]: info: CoreCommandRouter::volumioPushState Jul 11 09:57:39 volumio go-librespot[3071]: time="2024-07-11T09:57:39+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Jul 11 09:57:39 volumio volumio[882]: info: ------------------------------ 157ms Jul 11 09:57:39 volumio volumio[882]: info: ------------------------------ 158ms Jul 11 09:57:39 volumio volumio[882]: info: ------------------------------ 155ms Jul 11 09:57:39 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:39 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:39 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:39 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:39 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:39 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:41 volumio volumio[882]: info: Getting Spotify volume Jul 11 09:57:41 volumio volumio[882]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Jul 11 09:57:41 volumio volumio[882]: info: CoreCommandRouter::volumioGetState Jul 11 09:57:41 volumio volumio[882]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 11 09:57:41 volumio volumio[882]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 11 09:57:41 volumio volumio[882]: Error: connect ETIMEDOUT 199.59.150.45:80 Jul 11 09:57:41 volumio volumio[882]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Jul 11 09:57:41 volumio volumio[882]: errno: -110, Jul 11 09:57:41 volumio volumio[882]: code: 'ETIMEDOUT', Jul 11 09:57:41 volumio volumio[882]: syscall: 'connect', Jul 11 09:57:41 volumio volumio[882]: address: '199.59.150.45', Jul 11 09:57:41 volumio volumio[882]: port: 80 Jul 11 09:57:41 volumio volumio[882]: } Jul 11 09:57:41 volumio volumio[882]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 11 09:57:42 volumio sudo[3149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-11 09:56 Jul 11 09:57:42 volumio sudo[3149]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"