-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Mon 2025-02-24 21:16:32 CST. -- Feb 24 21:15:02 volumio volumio[10471]: info: Initializing connection to go-librespot Websocket Feb 24 21:15:02 volumio go-librespot[11265]: time="2025-02-24T21:15:02+08:00" level=debug msg="new websocket client" Feb 24 21:15:02 volumio volumio[10471]: info: Connection to go-librespot Websocket established Feb 24 21:15:05 volumio go-librespot[11265]: time="2025-02-24T21:15:05+08:00" level=debug msg="obtained new client token: AACfcxoJTlbOt5QMunKbG2ofYavE+4+DTTKTP14i3bZrddRPRgjZMioNLYrpw5l+d54vVrmzSZC7x8zpCzarOBpnbnce9AwGpWvfUIc5Xf+fwghH07t1ycLXYiEilFnmO0YjCxbXnpXyiFb/N1VHJ20pJW6HbD5fh2ZDMqGHGgPk1gDVNRWOMsDDDsR+yb42GIpc9OBJPHWx5Ku1wDYLmOQYNXTgFBVYNU5kRhQsX2Uvv4R3+9TfJsVRbbMdvc0=" Feb 24 21:15:05 volumio volumio[10471]: info: Getting Spotify volume Feb 24 21:15:05 volumio volumio[10471]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 21:15:05 volumio volumio[10471]: info: CoreCommandRouter::volumioGetState Feb 24 21:15:05 volumio volumio[10471]: info: CorePlayQueue::getTrack 1 Feb 24 21:15:05 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:06 volumio volumio[10471]: info: CoreCommandRouter::volumioPlay Feb 24 21:15:06 volumio volumio[10471]: info: CoreStateMachine::play index 0 Feb 24 21:15:06 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:06 volumio volumio[10471]: info: CoreStateMachine::stop Feb 24 21:15:06 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:06 volumio volumio[10471]: info: CoreStateMachine::play index undefined Feb 24 21:15:06 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:06 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:06 volumio volumio[10471]: info: CoreStateMachine::startPlaybackTimer Feb 24 21:15:06 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:06 volumio volumio[10471]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/无损U盘/酷我下载/Achim Reichel - Aloha Heja He.flac Feb 24 21:15:06 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand stop Feb 24 21:15:06 volumio volumio[10471]: info: sendMpdCommand stop took 0 milliseconds Feb 24 21:15:06 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand clear Feb 24 21:15:06 volumio volumio[10471]: info: Feb 24 21:15:06 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:06 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:06 volumio volumio[10471]: info: sendMpdCommand clear took 1 milliseconds Feb 24 21:15:06 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/无损U盘/酷我下载/Achim Reichel - Aloha Heja He.flac" Feb 24 21:15:06 volumio volumio[10471]: info: Feb 24 21:15:06 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:06 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:06 volumio volumio[10471]: info: Feb 24 21:15:06 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:06 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:06 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:06 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:06 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:06 volumio volumio[10471]: info: ------------------------------ 5ms Feb 24 21:15:06 volumio volumio[10471]: info: ------------------------------ 3ms Feb 24 21:15:06 volumio volumio[10471]: info: ------------------------------ 2ms Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:07 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:07 volumio volumio[10471]: info: CoreStateMachine::setRandom true Feb 24 21:15:07 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:07 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:07 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:07 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:07 volumio volumio[10471]: info: CoreStateMachine::setRandom false Feb 24 21:15:07 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:07 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:07 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:07 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:09 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:09 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:09 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:09 volumio volumio[10471]: info: CoreStateMachine::setRandom true Feb 24 21:15:09 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:09 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:09 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:09 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:09 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:10 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:10 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:10 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:10 volumio volumio[10471]: info: CoreStateMachine::setRandom false Feb 24 21:15:10 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:10 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:10 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:10 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:10 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:11 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:11 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:11 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:11 volumio volumio[10471]: info: CoreStateMachine::setRandom true Feb 24 21:15:11 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:11 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:11 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:11 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:11 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:12 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:12 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:12 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:12 volumio volumio[10471]: info: CoreStateMachine::setRandom false Feb 24 21:15:12 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:12 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:12 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:12 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:12 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:13 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:13 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:13 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:13 volumio volumio[10471]: info: CoreStateMachine::setRandom true Feb 24 21:15:13 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:13 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:13 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:13 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:13 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:13 volumio go-librespot[11265]: time="2025-02-24T21:15:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 24 21:15:14 volumio volumio[10471]: info: CoreCommandRouter::volumioPlay Feb 24 21:15:14 volumio volumio[10471]: info: CoreStateMachine::play index 0 Feb 24 21:15:14 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:14 volumio volumio[10471]: info: CoreStateMachine::stop Feb 24 21:15:14 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:14 volumio volumio[10471]: info: CoreStateMachine::play index undefined Feb 24 21:15:14 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:14 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:14 volumio volumio[10471]: info: CoreStateMachine::startPlaybackTimer Feb 24 21:15:14 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:14 volumio volumio[10471]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/无损U盘/酷我下载/Achim Reichel - Aloha Heja He.flac Feb 24 21:15:14 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand stop Feb 24 21:15:14 volumio volumio[10471]: info: sendMpdCommand stop took 2 milliseconds Feb 24 21:15:14 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand clear Feb 24 21:15:14 volumio volumio[10471]: info: Feb 24 21:15:14 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:14 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:14 volumio volumio[10471]: info: sendMpdCommand clear took 2 milliseconds Feb 24 21:15:14 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/无损U盘/酷我下载/Achim Reichel - Aloha Heja He.flac" Feb 24 21:15:14 volumio volumio[10471]: info: Feb 24 21:15:14 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:14 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:14 volumio volumio[10471]: info: Feb 24 21:15:14 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:14 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:14 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:14 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:14 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:14 volumio volumio[10471]: info: ------------------------------ 5ms Feb 24 21:15:14 volumio volumio[10471]: info: ------------------------------ 3ms Feb 24 21:15:14 volumio volumio[10471]: info: ------------------------------ 3ms Feb 24 21:15:15 volumio volumio[10471]: info: CoreCommandRouter::volumioRandom Feb 24 21:15:15 volumio volumio[10471]: info: CoreCommandRouter::writePlayerControls Feb 24 21:15:15 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:15 volumio volumio[10471]: info: CoreStateMachine::setRandom false Feb 24 21:15:15 volumio volumio[10471]: info: CoreStateMachine::pushState Feb 24 21:15:15 volumio volumio[10471]: info: CorePlayQueue::getTrack 0 Feb 24 21:15:15 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 24 21:15:15 volumio volumio[10471]: info: CoreCommandRouter::volumioPushState Feb 24 21:15:15 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:16 volumio volumio[10471]: info: CoreCommandRouter::volumioPlay Feb 24 21:15:16 volumio volumio[10471]: info: CoreStateMachine::play index 1 Feb 24 21:15:16 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:16 volumio volumio[10471]: info: CoreStateMachine::stop Feb 24 21:15:16 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:16 volumio volumio[10471]: info: CoreStateMachine::play index undefined Feb 24 21:15:16 volumio volumio[10471]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 24 21:15:16 volumio volumio[10471]: info: CorePlayQueue::getTrack 1 Feb 24 21:15:16 volumio volumio[10471]: info: CoreStateMachine::startPlaybackTimer Feb 24 21:15:16 volumio volumio[10471]: info: CorePlayQueue::getTrack 1 Feb 24 21:15:16 volumio volumio[10471]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/无损U盘/酷我下载/BEYOND - 光辉岁月.flac Feb 24 21:15:16 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand stop Feb 24 21:15:16 volumio volumio[10471]: info: sendMpdCommand stop took 1 milliseconds Feb 24 21:15:16 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand clear Feb 24 21:15:16 volumio volumio[10471]: info: Feb 24 21:15:16 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:16 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:16 volumio volumio[10471]: info: sendMpdCommand clear took 1 milliseconds Feb 24 21:15:16 volumio volumio[10471]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/无损U盘/酷我下载/BEYOND - 光辉岁月.flac" Feb 24 21:15:16 volumio volumio[10471]: info: Feb 24 21:15:16 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:16 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:16 volumio volumio[10471]: info: Feb 24 21:15:16 volumio volumio[10471]: ---------------------------- MPD announces system playlist update Feb 24 21:15:16 volumio volumio[10471]: info: Ignoring MPD Status Update Feb 24 21:15:16 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:16 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:16 volumio volumio[10471]: error: updateQueue error: null Feb 24 21:15:16 volumio volumio[10471]: info: ------------------------------ 3ms Feb 24 21:15:16 volumio volumio[10471]: info: ------------------------------ 3ms Feb 24 21:15:16 volumio volumio[10471]: info: ------------------------------ 2ms Feb 24 21:15:18 volumio volumio[10471]: info: Listing playlists Feb 24 21:15:19 volumio go-librespot[11265]: time="2025-02-24T21:15:19+08:00" level=debug msg="completed keyexchange" Feb 24 21:15:19 volumio go-librespot[11265]: time="2025-02-24T21:15:19+08:00" level=debug msg="completed challenge" Feb 24 21:15:19 volumio go-librespot[11265]: time="2025-02-24T21:15:19+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" Feb 24 21:15:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 21:15:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 21:15:19 volumio volumio[10471]: (node:10471) UnhandledPromiseRejectionWarning: Error: socket hang up Feb 24 21:15:19 volumio volumio[10471]: at connResetException (internal/errors.js:607:14) Feb 24 21:15:19 volumio volumio[10471]: at Socket.socketOnEnd (_http_client.js:493:23) Feb 24 21:15:19 volumio volumio[10471]: at Socket.emit (events.js:327:22) Feb 24 21:15:19 volumio volumio[10471]: at endReadableNT (internal/streams/readable.js:1327:12) Feb 24 21:15:19 volumio volumio[10471]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Feb 24 21:15:19 volumio volumio[10471]: (node:10471) 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: 20) Feb 24 21:15:19 volumio volumio[10471]: info: Connection to go-librespot Websocket closed Feb 24 21:15:22 volumio volumio[10471]: info: Initializing connection to go-librespot Websocket Feb 24 21:15:22 volumio volumio[10471]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 21:15:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 21:15:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Feb 24 21:15:23 volumio systemd[1]: Stopped go-librespot Daemon. Feb 24 21:15:23 volumio systemd[1]: Started go-librespot Daemon. Feb 24 21:15:23 volumio go-librespot[11312]: Librespot-go daemon starting... Feb 24 21:15:23 volumio go-librespot[11312]: time="2025-02-24T21:15:23+08:00" level=info msg="generated new device id: 2ff856d00a1954675375339fb58903bfeea47e89" Feb 24 21:15:23 volumio go-librespot[11312]: time="2025-02-24T21:15:23+08:00" level=debug msg="stored credentials not found" Feb 24 21:15:25 volumio volumio[10471]: info: Initializing connection to go-librespot Websocket Feb 24 21:15:25 volumio go-librespot[11312]: time="2025-02-24T21:15:25+08:00" level=debug msg="new websocket client" Feb 24 21:15:25 volumio volumio[10471]: info: Connection to go-librespot Websocket established Feb 24 21:15:28 volumio go-librespot[11312]: time="2025-02-24T21:15:28+08:00" level=debug msg="obtained new client token: AADgRfapDWZlezYPNY9csbC95xVTE9FxcGLmdtLiT7R2jNOIA40h5tNV4auuHJJliVcGPeRxb4Ig3vYN0+ceUug1g7OcZt149Na/vGmYNDC3v5SxH/scsmtD03UcL+pS9d0+zxxFtCzLfNJC6HWb5ER7KeQzBYIK9I3B2WbB50oYT5b22N4YzDl8+oH92iLJr9EaQgYejQaSJX7xCgwjqCQgzhrA6X6cA7OaBbMINTmn4ZeLI10pDMOWdzW10GlAIA==" Feb 24 21:15:28 volumio volumio[10471]: info: Getting Spotify volume Feb 24 21:15:28 volumio volumio[10471]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 21:15:28 volumio volumio[10471]: info: CoreCommandRouter::volumioGetState Feb 24 21:15:28 volumio volumio[10471]: info: CorePlayQueue::getTrack 1 Feb 24 21:15:28 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:15:30 volumio volumio[10471]: info: CorePlayQueue::getTrack 1 Feb 24 21:15:30 volumio volumio[10471]: info: CoreCommandRouter::executeOnPlugin: mpd , goto Feb 24 21:15:30 volumio volumio[10471]: error: Listalbum songs error: null Feb 24 21:15:30 volumio volumio[10471]: 404 Feb 24 21:15:37 volumio go-librespot[11312]: time="2025-02-24T21:15:37+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 24 21:15:43 volumio go-librespot[11312]: time="2025-02-24T21:15:43+08:00" level=debug msg="completed keyexchange" Feb 24 21:15:43 volumio go-librespot[11312]: time="2025-02-24T21:15:43+08:00" level=debug msg="completed challenge" Feb 24 21:15:43 volumio go-librespot[11312]: time="2025-02-24T21:15:43+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" Feb 24 21:15:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 21:15:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 21:15:43 volumio volumio[10471]: (node:10471) UnhandledPromiseRejectionWarning: Error: socket hang up Feb 24 21:15:43 volumio volumio[10471]: at connResetException (internal/errors.js:607:14) Feb 24 21:15:43 volumio volumio[10471]: at Socket.socketOnEnd (_http_client.js:493:23) Feb 24 21:15:43 volumio volumio[10471]: at Socket.emit (events.js:327:22) Feb 24 21:15:43 volumio volumio[10471]: at endReadableNT (internal/streams/readable.js:1327:12) Feb 24 21:15:43 volumio volumio[10471]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Feb 24 21:15:43 volumio volumio[10471]: (node:10471) 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: 21) Feb 24 21:15:43 volumio volumio[10471]: info: Connection to go-librespot Websocket closed Feb 24 21:15:46 volumio volumio[10471]: info: Initializing connection to go-librespot Websocket Feb 24 21:15:46 volumio volumio[10471]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 21:15:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 21:15:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Feb 24 21:15:47 volumio systemd[1]: Stopped go-librespot Daemon. Feb 24 21:15:47 volumio systemd[1]: Started go-librespot Daemon. Feb 24 21:15:47 volumio go-librespot[11321]: Librespot-go daemon starting... Feb 24 21:15:47 volumio go-librespot[11321]: time="2025-02-24T21:15:47+08:00" level=info msg="generated new device id: 44cece83739d3bac7d64ea4cbf2b403b9c5b04e3" Feb 24 21:15:47 volumio go-librespot[11321]: time="2025-02-24T21:15:47+08:00" level=debug msg="stored credentials not found" Feb 24 21:15:49 volumio volumio[10471]: info: Initializing connection to go-librespot Websocket Feb 24 21:15:49 volumio go-librespot[11321]: time="2025-02-24T21:15:49+08:00" level=debug msg="new websocket client" Feb 24 21:15:49 volumio volumio[10471]: info: Connection to go-librespot Websocket established Feb 24 21:15:52 volumio volumio[10471]: info: Getting Spotify volume Feb 24 21:15:52 volumio volumio[10471]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Feb 24 21:15:52 volumio volumio[10471]: info: CoreCommandRouter::volumioGetState Feb 24 21:15:52 volumio volumio[10471]: info: CorePlayQueue::getTrack 1 Feb 24 21:15:52 volumio volumio[10471]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 24 21:16:01 volumio go-librespot[11321]: time="2025-02-24T21:16:01+08:00" level=debug msg="obtained new client token: AABhnkGJvQX7q4L+ZWCW4YfN2WHUnlxFdc9iKmn7KeSt2xmuELZFaetoZVLBAP20U+9UI6ebDhIR8g6JmbfoaJi/ualcsJnWNmqqrUmthgAtD7Q1ltUwMLU3X0JQRSCdbJo1M06JPQP4h4ZsLzFvbt0DiEuVtxwK6vVzI3N5SN4V8/9wO5am6FdjVT1YHSNXTSM47Np+YKnj2EB01d3R0NW6TA/8bqsz7424gIxfGYfwVqSkxIPotFIz9x12IDe/fQ==" Feb 24 21:16:13 volumio go-librespot[11321]: time="2025-02-24T21:16:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Feb 24 21:16:24 volumio go-librespot[11321]: time="2025-02-24T21:16:24+08:00" level=debug msg="completed keyexchange" Feb 24 21:16:25 volumio go-librespot[11321]: time="2025-02-24T21:16:25+08:00" level=debug msg="completed challenge" Feb 24 21:16:25 volumio go-librespot[11321]: time="2025-02-24T21:16:25+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" Feb 24 21:16:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Feb 24 21:16:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Feb 24 21:16:25 volumio volumio[10471]: (node:10471) UnhandledPromiseRejectionWarning: Error: socket hang up Feb 24 21:16:25 volumio volumio[10471]: at connResetException (internal/errors.js:607:14) Feb 24 21:16:25 volumio volumio[10471]: at Socket.socketOnEnd (_http_client.js:493:23) Feb 24 21:16:25 volumio volumio[10471]: at Socket.emit (events.js:327:22) Feb 24 21:16:25 volumio volumio[10471]: at endReadableNT (internal/streams/readable.js:1327:12) Feb 24 21:16:25 volumio volumio[10471]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Feb 24 21:16:25 volumio volumio[10471]: (node:10471) 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: 22) Feb 24 21:16:25 volumio volumio[10471]: info: Connection to go-librespot Websocket closed Feb 24 21:16:28 volumio volumio[10471]: info: Initializing connection to go-librespot Websocket Feb 24 21:16:28 volumio volumio[10471]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Feb 24 21:16:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Feb 24 21:16:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Feb 24 21:16:28 volumio systemd[1]: Stopped go-librespot Daemon. Feb 24 21:16:28 volumio systemd[1]: Started go-librespot Daemon. Feb 24 21:16:28 volumio go-librespot[11371]: Librespot-go daemon starting... Feb 24 21:16:28 volumio go-librespot[11371]: time="2025-02-24T21:16:28+08:00" level=info msg="generated new device id: 1b2a4e0afb674a2dddee2645a1c94e35bef92ad5" Feb 24 21:16:28 volumio go-librespot[11371]: time="2025-02-24T21:16:28+08:00" level=debug msg="stored credentials not found" Feb 24 21:16:31 volumio volumio[10471]: info: Initializing connection to go-librespot Websocket Feb 24 21:16:31 volumio go-librespot[11371]: time="2025-02-24T21:16:31+08:00" level=debug msg="new websocket client" Feb 24 21:16:31 volumio volumio[10471]: info: Connection to go-librespot Websocket established Feb 24 21:16:32 volumio volumio[10471]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 21:16:32 volumio volumio[10471]: Error: connect ETIMEDOUT 118.193.240.41:443 Feb 24 21:16:32 volumio volumio[10471]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Feb 24 21:16:32 volumio volumio[10471]: errno: -110, Feb 24 21:16:32 volumio volumio[10471]: code: 'ETIMEDOUT', Feb 24 21:16:32 volumio volumio[10471]: syscall: 'connect', Feb 24 21:16:32 volumio volumio[10471]: address: '118.193.240.41', Feb 24 21:16:32 volumio volumio[10471]: port: 443 Feb 24 21:16:32 volumio volumio[10471]: } Feb 24 21:16:32 volumio volumio[10471]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 24 21:16:32 volumio sudo[11389]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-24 21:15 Feb 24 21:16:32 volumio sudo[11389]: 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"