-- Logs begin at Sat 2024-04-20 17:38:21 CST, end at Sat 2024-04-20 18:02:43 CST. -- Apr 20 18:01:01 volumio kernel: fat__get_entry: 1270 callbacks suppressed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:01 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:06 volumio kernel: fat__get_entry: 1270 callbacks suppressed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:06 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:07 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 9 Apr 20 18:01:07 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:01:07 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:01:08 volumio volumio[845]: info: peppy_screensaver: Start PeppyMeter Apr 20 18:01:12 volumio kernel: fat__get_entry: 1526 callbacks suppressed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:12 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:17 volumio kernel: fat__get_entry: 1270 callbacks suppressed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:17 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:22 volumio volumio[845]: info: peppy_screensaver: Start PeppyMeter Apr 20 18:01:23 volumio kernel: fat__get_entry: 1270 callbacks suppressed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:23 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:28 volumio kernel: fat__get_entry: 1270 callbacks suppressed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:28 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:33 volumio kernel: fat__get_entry: 1270 callbacks suppressed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:33 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:37 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 9 Apr 20 18:01:37 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:01:37 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:01:38 volumio volumio[845]: info: peppy_screensaver: Start PeppyMeter Apr 20 18:01:40 volumio kernel: fat__get_entry: 1526 callbacks suppressed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:40 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:46 volumio kernel: fat__get_entry: 1270 callbacks suppressed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:46 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:50 volumio go-librespot[7482]: time="2024-04-20T18:01:50+08:00" level=error msg="did not receive last pong ack from accesspoint, 120s passed" Apr 20 18:01:50 volumio go-librespot[7482]: time="2024-04-20T18:01:50+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.1.5:40884->104.199.240.237:4070: use of closed network connection" Apr 20 18:01:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:01:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:01:50 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 20 18:01:50 volumio volumio[845]: at connResetException (internal/errors.js:607:14) Apr 20 18:01:50 volumio volumio[845]: at Socket.socketOnEnd (_http_client.js:493:23) Apr 20 18:01:50 volumio volumio[845]: at Socket.emit (events.js:327:22) Apr 20 18:01:50 volumio volumio[845]: at endReadableNT (internal/streams/readable.js:1327:12) Apr 20 18:01:50 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Apr 20 18:01:50 volumio volumio[845]: (node:845) 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: 220) Apr 20 18:01:50 volumio volumio[845]: info: Connection to go-librespot Websocket closed Apr 20 18:01:51 volumio kernel: fat__get_entry: 1014 callbacks suppressed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:51 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:51 volumio volumio[845]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 20 18:01:51 volumio volumio[845]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 20 18:01:52 volumio volumio[845]: error: [yt-cast-receiver] (YouTube) Error occurred in SendMessageTask: Apr 20 18:01:52 volumio volumio[845]: LoungeScreenDisconnected { Apr 20 18:01:52 volumio volumio[845]: AID: null, Apr 20 18:01:52 volumio volumio[845]: name: 'loungeScreenDisconnected', Apr 20 18:01:52 volumio volumio[845]: payload: {} Apr 20 18:01:52 volumio volumio[845]: } Apr 20 18:01:52 volumio volumio[845]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 20 18:01:52 volumio volumio[845]: Stack trace: Apr 20 18:01:52 volumio volumio[845]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 20 18:01:52 volumio volumio[845]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 20 18:01:52 volumio volumio[845]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 20 18:01:52 volumio volumio[845]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 20 18:01:52 volumio volumio[845]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Apr 20 18:01:52 volumio volumio[845]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) 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: 222) Apr 20 18:01:52 volumio volumio[845]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Apr 20 18:01:52 volumio volumio[845]: LoungeScreenDisconnected { Apr 20 18:01:52 volumio volumio[845]: AID: null, Apr 20 18:01:52 volumio volumio[845]: name: 'loungeScreenDisconnected', Apr 20 18:01:52 volumio volumio[845]: payload: {} Apr 20 18:01:52 volumio volumio[845]: } Apr 20 18:01:52 volumio volumio[845]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 20 18:01:52 volumio volumio[845]: Stack trace: Apr 20 18:01:52 volumio volumio[845]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 20 18:01:52 volumio volumio[845]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 20 18:01:52 volumio volumio[845]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 20 18:01:52 volumio volumio[845]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 20 18:01:52 volumio volumio[845]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Apr 20 18:01:52 volumio volumio[845]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) 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: 224) Apr 20 18:01:52 volumio volumio[845]: error: [yt-cast-receiver] (YouTube) Error occurred in SendMessageTask: Apr 20 18:01:52 volumio volumio[845]: LoungeScreenDisconnected { Apr 20 18:01:52 volumio volumio[845]: AID: null, Apr 20 18:01:52 volumio volumio[845]: name: 'loungeScreenDisconnected', Apr 20 18:01:52 volumio volumio[845]: payload: {} Apr 20 18:01:52 volumio volumio[845]: } Apr 20 18:01:52 volumio volumio[845]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 20 18:01:52 volumio volumio[845]: Stack trace: Apr 20 18:01:52 volumio volumio[845]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 20 18:01:52 volumio volumio[845]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 20 18:01:52 volumio volumio[845]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 20 18:01:52 volumio volumio[845]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 20 18:01:52 volumio volumio[845]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Apr 20 18:01:52 volumio volumio[845]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) 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: 226) Apr 20 18:01:52 volumio volumio[845]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Apr 20 18:01:52 volumio volumio[845]: LoungeScreenDisconnected { Apr 20 18:01:52 volumio volumio[845]: AID: null, Apr 20 18:01:52 volumio volumio[845]: name: 'loungeScreenDisconnected', Apr 20 18:01:52 volumio volumio[845]: payload: {} Apr 20 18:01:52 volumio volumio[845]: } Apr 20 18:01:52 volumio volumio[845]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 20 18:01:52 volumio volumio[845]: Stack trace: Apr 20 18:01:52 volumio volumio[845]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 20 18:01:52 volumio volumio[845]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 20 18:01:52 volumio volumio[845]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 20 18:01:52 volumio volumio[845]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 20 18:01:52 volumio volumio[845]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 20 18:01:52 volumio volumio[845]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Apr 20 18:01:52 volumio volumio[845]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Apr 20 18:01:52 volumio volumio[845]: at runMicrotasks () Apr 20 18:01:52 volumio volumio[845]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:01:52 volumio volumio[845]: (node:845) 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: 228) Apr 20 18:01:52 volumio volumio[845]: info: peppy_screensaver: Start PeppyMeter Apr 20 18:01:53 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:01:53 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:01:53 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:01:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 235. Apr 20 18:01:53 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:01:53 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:01:53 volumio go-librespot[8209]: Librespot-go daemon starting... Apr 20 18:01:53 volumio go-librespot[8209]: time="2024-04-20T18:01:53+08:00" level=info msg="generated new device id: ccf42f2b1d98f1f91e7789561d2e428faa23cbc1" Apr 20 18:01:53 volumio go-librespot[8209]: time="2024-04-20T18:01:53+08:00" level=debug msg="stored credentials not found" Apr 20 18:01:53 volumio go-librespot[8209]: time="2024-04-20T18:01:53+08:00" level=debug msg="obtained new client token: AAClPMd+4sytceHLfxG+2EPLrWV80ufVVzqOeHSp+0aM9yL2cNz0Zr3wGsFYijtdvqCPO0isaSlr9nvcL0LJUgxOHkU/rA22TDLA7ILR72mNycdHaw4UgbZ+41NQm8NXouclVbaD7LZGew2IA4BvhOpkS0Jfozg7GFITyUIpI3umdKkeoV4QkP3eCR1PEJaVoZONxqXQ2snVbiFLeFwxL8pHMrzMdR3/bpn8bDvQTs0K5E31n7ej19EJbiathQ==" Apr 20 18:01:53 volumio go-librespot[8209]: time="2024-04-20T18:01:53+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]" Apr 20 18:01:54 volumio go-librespot[8209]: time="2024-04-20T18:01:54+08:00" level=debug msg="completed keyexchange" Apr 20 18:01:55 volumio go-librespot[8209]: time="2024-04-20T18:01:55+08:00" level=debug msg="completed challenge" Apr 20 18:01:55 volumio go-librespot[8209]: time="2024-04-20T18:01:55+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" Apr 20 18:01:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:01:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:01:56 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:01:56 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:01:57 volumio kernel: fat__get_entry: 758 callbacks suppressed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:01:57 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:01:58 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:01:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 236. Apr 20 18:01:58 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:01:58 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:01:58 volumio go-librespot[8228]: Librespot-go daemon starting... Apr 20 18:01:58 volumio go-librespot[8228]: time="2024-04-20T18:01:58+08:00" level=info msg="generated new device id: 3da65287b4f241eee56183c6ab261b33f4a92ea6" Apr 20 18:01:58 volumio go-librespot[8228]: time="2024-04-20T18:01:58+08:00" level=debug msg="stored credentials not found" Apr 20 18:01:58 volumio go-librespot[8228]: time="2024-04-20T18:01:58+08:00" level=debug msg="obtained new client token: AACqoZUT6rgVYdzdVoXGveVXmk3CyU+cDuqXdBbWbhe0y6W0dpSKD6Nmsb8DbJxVhAbnuWAJw8s69b/Epoi4DUrobWBO/5VZZeaf4/ALw6xCugrmN1qOlLbeDu0Oy5IPVDC6R5QEWpqUkjZaJ+HProIwijaCeK3rL/0W3uViL3l5fasanr5MxYG3/G1FN+KsTQa+DDFo/Zvm+kjTB13m7yLLhR0mD14+liQMlk98vhYU6DJ923lBXZEcKV3ugw==" Apr 20 18:01:59 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:01:59 volumio go-librespot[8228]: time="2024-04-20T18:01:59+08:00" level=debug msg="new websocket client" Apr 20 18:01:59 volumio volumio[845]: info: Connection to go-librespot Websocket established Apr 20 18:01:59 volumio go-librespot[8228]: time="2024-04-20T18:01:59+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]" Apr 20 18:01:59 volumio go-librespot[8228]: time="2024-04-20T18:01:59+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:00 volumio go-librespot[8228]: time="2024-04-20T18:02:00+08:00" level=debug msg="completed challenge" Apr 20 18:02:00 volumio go-librespot[8228]: time="2024-04-20T18:02:00+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" Apr 20 18:02:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:00 volumio volumio[845]: info: Connection to go-librespot Websocket closed Apr 20 18:02:02 volumio volumio[845]: info: Getting Spotify volume Apr 20 18:02:02 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:02 volumio volumio[845]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:02:02 volumio volumio[845]: (node:845) 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: 229) Apr 20 18:02:02 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 20 18:02:02 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:02:02 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:02 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:03 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:03 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 237. Apr 20 18:02:03 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:03 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:03 volumio go-librespot[8246]: Librespot-go daemon starting... Apr 20 18:02:03 volumio go-librespot[8246]: time="2024-04-20T18:02:03+08:00" level=info msg="generated new device id: 237b43b817f5a67944787cb2f6fd1d359a0e7eac" Apr 20 18:02:03 volumio go-librespot[8246]: time="2024-04-20T18:02:03+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:03 volumio kernel: fat__get_entry: 1014 callbacks suppressed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:02:03 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:02:04 volumio go-librespot[8246]: time="2024-04-20T18:02:04+08:00" level=debug msg="obtained new client token: AADoaUoOi82q5ZlrYAVun4W8dow3X4P/5uiUbunnycTljInMyl7KDvnSwvAWdmsPS54X+PXq4YMFEqLSRSCqnKPbRx1rzqs9Fb9tAb99hxBoLAYdyFUSQNfP3hF7FpmzOpuTe2W55yz5l+INCF5zpZ2ljZSvWcWLJt7mEb4pEOMyuXl4pMR2J/qJ9D2HH62cvUvErTIrPWU1o1+Dap416qgYaYjKZ7R0gO71g+2qXkphe3DsivgTD0DW0MLl5A==" Apr 20 18:02:04 volumio go-librespot[8246]: time="2024-04-20T18:02:04+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]" Apr 20 18:02:04 volumio go-librespot[8246]: time="2024-04-20T18:02:04+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:05 volumio go-librespot[8246]: time="2024-04-20T18:02:05+08:00" level=debug msg="completed challenge" Apr 20 18:02:05 volumio go-librespot[8246]: time="2024-04-20T18:02:05+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" Apr 20 18:02:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:06 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:06 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:07 volumio volumio[845]: info: peppy_screensaver: Start PeppyMeter Apr 20 18:02:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 238. Apr 20 18:02:08 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:08 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:08 volumio go-librespot[8330]: Librespot-go daemon starting... Apr 20 18:02:08 volumio go-librespot[8330]: time="2024-04-20T18:02:08+08:00" level=info msg="generated new device id: b8356912c5e8aad94f428c60939ae359e7d04645" Apr 20 18:02:08 volumio go-librespot[8330]: time="2024-04-20T18:02:08+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:08 volumio go-librespot[8330]: time="2024-04-20T18:02:08+08:00" level=debug msg="obtained new client token: AAASob6vZv8ns/CFja+1LHI8aEFQnhOSmKG7wydsdhBN0Lc3SBA2/fJDHfKHSvKWzYusr/vpeT76efOupUAcrJ9k57lEDAWslu5T4iCwAhbZW85R7BrbQKJWi9SC/WJV2AeWGPC4T/e1eCOdGlcdBeapV7lblssyLaq0SvdlqhDRGRuBgo9GsgWKzSOMYx8fmypkibDVUm18ika67h5d7e9EuKGdmJL7k+4jEGYT2iuc/+wCTUimAiRCDPSK8Q==" Apr 20 18:02:09 volumio go-librespot[8330]: time="2024-04-20T18:02:09+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]" Apr 20 18:02:09 volumio kernel: fat__get_entry: 1014 callbacks suppressed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:02:09 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:02:09 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:09 volumio go-librespot[8330]: time="2024-04-20T18:02:09+08:00" level=debug msg="new websocket client" Apr 20 18:02:09 volumio volumio[845]: info: Connection to go-librespot Websocket established Apr 20 18:02:09 volumio go-librespot[8330]: time="2024-04-20T18:02:09+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:10 volumio go-librespot[8330]: time="2024-04-20T18:02:10+08:00" level=debug msg="completed challenge" Apr 20 18:02:10 volumio go-librespot[8330]: time="2024-04-20T18:02:10+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" Apr 20 18:02:10 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:10 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:10 volumio volumio[845]: info: Connection to go-librespot Websocket closed Apr 20 18:02:12 volumio volumio[845]: info: Getting Spotify volume Apr 20 18:02:12 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:12 volumio volumio[845]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:02:12 volumio volumio[845]: (node:845) 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: 230) Apr 20 18:02:12 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 20 18:02:12 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:02:12 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:12 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:13 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:13 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 239. Apr 20 18:02:13 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:13 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:13 volumio go-librespot[8349]: Librespot-go daemon starting... Apr 20 18:02:13 volumio go-librespot[8349]: time="2024-04-20T18:02:13+08:00" level=info msg="generated new device id: 8aae644fa08332af097e0797fbc83a01a148e96d" Apr 20 18:02:13 volumio go-librespot[8349]: time="2024-04-20T18:02:13+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:13 volumio go-librespot[8349]: time="2024-04-20T18:02:13+08:00" level=debug msg="obtained new client token: AADCWwQTsLPD6RUMHsbg0WUx+6Plh1vrovBrOaG2PTofb0rS7YMLl2T20Fct9CYkhxLVc9RKg8HrV9fVwTbsaQtmZP0p+FOy3XA13g8W/l7vgoPdGBtNUVsNd+2VVnQvM+965ZF8YJ7Ob1TNRxR5qe3Nu+AUvIX/dUJB2khMa7ICLSaTQGL1amAYqM24jd1+xWHMEqryBlMrsscDIIqzX8c1R+NBL0h8H7h8Rjfn3yPJUtvpHiNhqSDJ3FlbRw==" Apr 20 18:02:14 volumio go-librespot[8349]: time="2024-04-20T18:02:14+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]" Apr 20 18:02:14 volumio go-librespot[8349]: time="2024-04-20T18:02:14+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:15 volumio go-librespot[8349]: time="2024-04-20T18:02:15+08:00" level=debug msg="completed challenge" Apr 20 18:02:15 volumio go-librespot[8349]: time="2024-04-20T18:02:15+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" Apr 20 18:02:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:15 volumio kernel: fat__get_entry: 1014 callbacks suppressed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:02:15 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:02:16 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:16 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 240. Apr 20 18:02:18 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:18 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:18 volumio go-librespot[8367]: Librespot-go daemon starting... Apr 20 18:02:18 volumio go-librespot[8367]: time="2024-04-20T18:02:18+08:00" level=info msg="generated new device id: 03946e844898ba5c6784ad9b2ad668c386897ed6" Apr 20 18:02:18 volumio go-librespot[8367]: time="2024-04-20T18:02:18+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:18 volumio go-librespot[8367]: time="2024-04-20T18:02:18+08:00" level=debug msg="obtained new client token: AAAARGKkBhRX1pw0soO0nobD3nK6+952K31DhvbFPfJ5fArp7ia5E717/v5sAjkeV7WtFhHDlMPwCDyA94Ctt69pIwh6RTSE6qzD7REgUkQzqB5kZ7tMQy6QV4pwcbhmdczN+oAknL4hQhVrhQaTN9aS1QBZLZ+zVKfynAt1vopL3Lw2qu9DmB5N00SNE1/u4Qqet6VrzOGhjJLHN//qB8eiPubxT6sPFXjhgTxgpSKFgkTuJ3Mfkj3djbBbZQ==" Apr 20 18:02:19 volumio go-librespot[8367]: time="2024-04-20T18:02:19+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]" Apr 20 18:02:19 volumio go-librespot[8367]: time="2024-04-20T18:02:19+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:19 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:19 volumio go-librespot[8367]: time="2024-04-20T18:02:19+08:00" level=debug msg="new websocket client" Apr 20 18:02:19 volumio volumio[845]: info: Connection to go-librespot Websocket established Apr 20 18:02:19 volumio go-librespot[8367]: time="2024-04-20T18:02:19+08:00" level=debug msg="completed challenge" Apr 20 18:02:19 volumio go-librespot[8367]: time="2024-04-20T18:02: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" Apr 20 18:02:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:19 volumio volumio[845]: info: Connection to go-librespot Websocket closed Apr 20 18:02:22 volumio volumio[845]: info: Getting Spotify volume Apr 20 18:02:22 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:22 volumio volumio[845]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:02:22 volumio volumio[845]: (node:845) 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: 231) Apr 20 18:02:22 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 20 18:02:22 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:02:22 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:22 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:22 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 9 Apr 20 18:02:22 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:02:22 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:22 volumio kernel: fat__get_entry: 502 callbacks suppressed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:02:22 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:02:22 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:22 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 241. Apr 20 18:02:23 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:23 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:23 volumio go-librespot[8411]: Librespot-go daemon starting... Apr 20 18:02:23 volumio go-librespot[8411]: time="2024-04-20T18:02:23+08:00" level=info msg="generated new device id: 1a16b43880397de708d430cfca073a397f33fee2" Apr 20 18:02:23 volumio go-librespot[8411]: time="2024-04-20T18:02:23+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:23 volumio volumio[845]: info: peppy_screensaver: Start PeppyMeter Apr 20 18:02:23 volumio go-librespot[8411]: time="2024-04-20T18:02:23+08:00" level=debug msg="obtained new client token: AACcwBIXcwY/IYunqe6QNSCVyK8j7oyQhqVtq8m92HE1YscZT604/tjRVhMkA1XhnFSdFLq4vH+s/kRcpP7cbCJYkaY9podltkZKT670IQAzaLXVXeShrBmUO6jqhMGKs8en9dicn+V+CniOE6Zbu9UYI/wlH5VBfaFez9E81Bz74VHM/4ULSczlFSirj3sT9SrR+/Dt8TLcBPI4a/I6sy7uaO2BgTCGglFeQiHhx6EVoUEONPecO5y+yiGMyw==" Apr 20 18:02:23 volumio go-librespot[8411]: time="2024-04-20T18:02:23+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]" Apr 20 18:02:24 volumio go-librespot[8411]: time="2024-04-20T18:02:24+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:24 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio volumio[845]: error: updateQueue error: null Apr 20 18:02:24 volumio volumio[845]: error: updateQueue error: null Apr 20 18:02:24 volumio volumio[845]: error: updateQueue error: null Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 5ms Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 4 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 4ms Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 4 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 3ms Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 3 milliseconds Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 20 18:02:24 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState stateService stop Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::play index undefined Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 20 18:02:24 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState stateService stop Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: No code Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 20 18:02:24 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState stateService stop Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: No code Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::startPlaybackTimer Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::clearAddPlayTracks USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3 Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand stop Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 74ms Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 76ms Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 75ms Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand stop took 15 milliseconds Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand clear Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand clear took 32 milliseconds Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand add "USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3" Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: error: updateQueue error: null Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 46ms Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand add "USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3" took 44 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 44ms Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 43ms Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand play Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces system playlist update Apr 20 18:02:24 volumio volumio[845]: info: Ignoring MPD Status Update Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 33ms Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand play took 31 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio volumio[845]: info: ------------------------------ 30ms Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio go-librespot[8411]: time="2024-04-20T18:02:24+08:00" level=debug msg="completed challenge" Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Apr 20 18:02:24 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 217 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 218 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 217 milliseconds Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio volumio[845]: info: Apr 20 18:02:24 volumio volumio[845]: ---------------------------- MPD announces state update: player Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::getState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:02:24 volumio volumio[845]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 14 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand playlistinfo took 12 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand playlistinfo took 11 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand playlistinfo took 11 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 9 milliseconds Apr 20 18:02:24 volumio volumio[845]: info: sendMpdCommand status took 7 milliseconds Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::parseState Apr 20 18:02:24 volumio volumio[845]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: verbose: STATE SERVICE {"status":"play","position":0,"seek":445,"duration":207,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"½ñÒ¹ÓêÃÉÃÉ","artist":"ÀîÁáÓñ","album":null,"uri":"USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3","trackType":"mp3"} Apr 20 18:02:24 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState stateService play Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: verbose: STATE SERVICE {"status":"play","position":0,"seek":445,"duration":207,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"½ñÒ¹ÓêÃÉÃÉ","artist":"ÀîÁáÓñ","album":null,"uri":"USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3","trackType":"mp3"} Apr 20 18:02:24 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState stateService play Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:02:24 volumio volumio[845]: info: Received an update from plugin. extracting info from payload Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: verbose: STATE SERVICE {"status":"play","position":0,"seek":445,"duration":207,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"½ñÒ¹ÓêÃÉÃÉ","artist":"ÀîÁáÓñ","album":null,"uri":"USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3","trackType":"mp3"} Apr 20 18:02:24 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState stateService play Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:02:24 volumio volumio[845]: info: Received an update from plugin. extracting info from payload Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:24 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:24 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:24 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:25 volumio volumio[845]: info: ------------------------------ 256ms Apr 20 18:02:25 volumio volumio[845]: info: ------------------------------ 266ms Apr 20 18:02:25 volumio volumio[845]: info: ------------------------------ 267ms Apr 20 18:02:25 volumio volumio[845]: info: sendMpdCommand playlistinfo took 34 milliseconds Apr 20 18:02:25 volumio volumio[845]: info: sendMpdCommand playlistinfo took 33 milliseconds Apr 20 18:02:25 volumio volumio[845]: info: sendMpdCommand playlistinfo took 34 milliseconds Apr 20 18:02:25 volumio volumio[845]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:02:25 volumio volumio[845]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:02:25 volumio volumio[845]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:02:25 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":207,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"½ñÒ¹ÓêÃÉÃÉ","artist":"ÀîÁáÓñ","album":null,"uri":"USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3","trackType":"mp3"} Apr 20 18:02:25 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::syncState stateService play Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:02:25 volumio volumio[845]: info: Received an update from plugin. extracting info from payload Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:25 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":207,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"½ñÒ¹ÓêÃÉÃÉ","artist":"ÀîÁáÓñ","album":null,"uri":"USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3","trackType":"mp3"} Apr 20 18:02:25 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::syncState stateService play Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:02:25 volumio volumio[845]: info: Received an update from plugin. extracting info from payload Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:25 volumio volumio[845]: info: ControllerMpd::pushState Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::servicePushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":207,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"½ñÒ¹ÓêÃÉÃÉ","artist":"ÀîÁáÓñ","album":null,"uri":"USB/U15-32G/608.今夜雨蒙蒙 李玲玉.mp3","trackType":"mp3"} Apr 20 18:02:25 volumio volumio[845]: verbose: CURRENT POSITION 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::syncState stateService play Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:02:25 volumio volumio[845]: info: Received an update from plugin. extracting info from payload Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:25 volumio volumio[845]: info: CoreStateMachine::pushState Apr 20 18:02:25 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:25 volumio volumio[845]: info: CoreCommandRouter::volumioPushState Apr 20 18:02:25 volumio volumio[845]: info: ------------------------------ 122ms Apr 20 18:02:25 volumio volumio[845]: info: ------------------------------ 115ms Apr 20 18:02:25 volumio volumio[845]: info: ------------------------------ 114ms Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:25 volumio go-librespot[8411]: time="2024-04-20T18:02: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" Apr 20 18:02:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:25 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:26 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 242. Apr 20 18:02:28 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:28 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:28 volumio go-librespot[8438]: Librespot-go daemon starting... Apr 20 18:02:28 volumio go-librespot[8438]: time="2024-04-20T18:02:28+08:00" level=info msg="generated new device id: 130e4e0ed39d5c1554f0f5d020e667bbae9e0a40" Apr 20 18:02:28 volumio go-librespot[8438]: time="2024-04-20T18:02:28+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:29 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:29 volumio go-librespot[8438]: time="2024-04-20T18:02:29+08:00" level=debug msg="new websocket client" Apr 20 18:02:29 volumio volumio[845]: info: Connection to go-librespot Websocket established Apr 20 18:02:29 volumio go-librespot[8438]: time="2024-04-20T18:02:29+08:00" level=debug msg="obtained new client token: AACy48SUr+4A9ctWrUjfHYUUZMNxOtoMA94w3AthOWKXk5M9DnHigDYZxEj6qIOIbpoXfZ0FwCrZBovx4+lrElEZhSjjLLcBPHDw7snO69u3A6Ozau4SNoIo8pBzHR9aQ9/Eu+IYAaQFjnDnIR2AE6QgNUDhTDEwbnzeDFhS/7i3BFId8eebyxlJncrMY61Oar38uOSiH2I57WQnTZp53n3vy+0OKpBLz8eTBDoGCRHWxwFPPgIpusHO708=" Apr 20 18:02:29 volumio go-librespot[8438]: time="2024-04-20T18:02:29+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]" Apr 20 18:02:29 volumio go-librespot[8438]: time="2024-04-20T18:02:29+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:30 volumio go-librespot[8438]: time="2024-04-20T18:02:30+08:00" level=debug msg="completed challenge" Apr 20 18:02:30 volumio go-librespot[8438]: time="2024-04-20T18:02:30+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" Apr 20 18:02:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:30 volumio volumio[845]: info: Connection to go-librespot Websocket closed Apr 20 18:02:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:32 volumio volumio[845]: info: Getting Spotify volume Apr 20 18:02:32 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:32 volumio volumio[845]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:02:32 volumio volumio[845]: (node:845) 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: 232) Apr 20 18:02:32 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 20 18:02:32 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:02:32 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:32 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:33 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:33 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:33 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 243. Apr 20 18:02:33 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:33 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:33 volumio go-librespot[8456]: Librespot-go daemon starting... Apr 20 18:02:33 volumio go-librespot[8456]: time="2024-04-20T18:02:33+08:00" level=info msg="generated new device id: 6c553bebad9b7e3a90000f045fc2eac5b413d3a2" Apr 20 18:02:33 volumio go-librespot[8456]: time="2024-04-20T18:02:33+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:34 volumio go-librespot[8456]: time="2024-04-20T18:02:34+08:00" level=debug msg="obtained new client token: AACXgrZ1W8oab1174cP6vK/yh/LKP3zdnO7njlhf2gXA7lff4+deDoD3jPiIWhC4uRiAR8wC6K4PbKdZutrFscHZNIIuYNx7zE+Xj4ZMtSaCGDq7i+sgR8I3FzzvDzT9ZH84Hrhoa9EPE8/YRcLZHFRv0e4e/EdC1q5Q1Dx6ZC+6TiIGeG6LpRTDjwzM/tEgX8R185774KlLGCNdb8KJIKwDdfOLwUA6DB2AnHn8QJibHzHigjgTMLvxmXQ=" Apr 20 18:02:34 volumio go-librespot[8456]: time="2024-04-20T18:02: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]" Apr 20 18:02:34 volumio go-librespot[8456]: time="2024-04-20T18:02:34+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:35 volumio go-librespot[8456]: time="2024-04-20T18:02:35+08:00" level=debug msg="completed challenge" Apr 20 18:02:35 volumio go-librespot[8456]: time="2024-04-20T18:02: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" Apr 20 18:02:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:36 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:36 volumio volumio[845]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:02:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 244. Apr 20 18:02:38 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:02:38 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:02:38 volumio go-librespot[8475]: Librespot-go daemon starting... Apr 20 18:02:38 volumio go-librespot[8475]: time="2024-04-20T18:02:38+08:00" level=info msg="generated new device id: a3d54aa83871530c1be073a3c5e560a862adbdab" Apr 20 18:02:38 volumio go-librespot[8475]: time="2024-04-20T18:02:38+08:00" level=debug msg="stored credentials not found" Apr 20 18:02:39 volumio go-librespot[8475]: time="2024-04-20T18:02:39+08:00" level=debug msg="obtained new client token: AACGAETlpKGN4kh9x5qyujZF3UjRq5vqSxr/Fg782gmVY8EcusaA03MOwyVL4fAbcAeevMUUiJq9tdqH0QiHnXEe5Q2nTCpXdf6IhPBZlZ507hKhoR0yaAtm9aZ1zwVlMy1h03cb6sELdnK5Ze2zn7Eujekb4Fn5mKVfmQRMOIM1Ymz5D8ZyVoNTf1IWM8yINdkjSvS9440zLQFlDuA7lb78r/ynA4sD8x0hDhep0X2n3ONvWM7xRSLC4MU=" Apr 20 18:02:39 volumio go-librespot[8475]: time="2024-04-20T18:02: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-gew4.spotify.com:80]" Apr 20 18:02:39 volumio volumio[845]: info: Initializing connection to go-librespot Websocket Apr 20 18:02:39 volumio go-librespot[8475]: time="2024-04-20T18:02:39+08:00" level=debug msg="new websocket client" Apr 20 18:02:39 volumio volumio[845]: info: Connection to go-librespot Websocket established Apr 20 18:02:40 volumio go-librespot[8475]: time="2024-04-20T18:02:40+08:00" level=debug msg="completed keyexchange" Apr 20 18:02:40 volumio go-librespot[8475]: time="2024-04-20T18:02:40+08:00" level=debug msg="completed challenge" Apr 20 18:02:40 volumio go-librespot[8475]: time="2024-04-20T18:02:40+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" Apr 20 18:02:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:02:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:02:40 volumio volumio[845]: info: Connection to go-librespot Websocket closed Apr 20 18:02:42 volumio volumio[845]: info: Getting Spotify volume Apr 20 18:02:42 volumio volumio[845]: (node:845) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:02:42 volumio volumio[845]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:02:42 volumio volumio[845]: (node:845) 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: 233) Apr 20 18:02:42 volumio volumio[845]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 20 18:02:42 volumio volumio[845]: info: CoreCommandRouter::volumioGetState Apr 20 18:02:42 volumio volumio[845]: info: CorePlayQueue::getTrack 0 Apr 20 18:02:42 volumio volumio[845]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Apr 20 18:02:43 volumio volumio[845]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 20 18:02:43 volumio volumio[845]: Error: connect ETIMEDOUT 104.244.46.165:80 Apr 20 18:02:43 volumio volumio[845]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Apr 20 18:02:43 volumio volumio[845]: errno: -110, Apr 20 18:02:43 volumio volumio[845]: code: 'ETIMEDOUT', Apr 20 18:02:43 volumio volumio[845]: syscall: 'connect', Apr 20 18:02:43 volumio volumio[845]: address: '104.244.46.165', Apr 20 18:02:43 volumio volumio[845]: port: 80 Apr 20 18:02:43 volumio volumio[845]: } Apr 20 18:02:43 volumio volumio[845]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 20 18:02:43 volumio sudo[8525]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-20 18:01 Apr 20 18:02:43 volumio sudo[8525]: 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"