-- Logs begin at Fri 2024-05-17 22:57:28 CST, end at Wed 2024-09-04 17:25:54 CST. -- Sep 04 17:24:05 volumio go-librespot[11302]: time="2024-09-04T17:24:05+08:00" level=debug msg="completed keyexchange" Sep 04 17:24:05 volumio go-librespot[11302]: time="2024-09-04T17:24:05+08:00" level=debug msg="completed challenge" Sep 04 17:24:05 volumio go-librespot[11302]: time="2024-09-04T17:24: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" Sep 04 17:24:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 17:24:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 17:24:05 volumio volumio[865]: (node:865) UnhandledPromiseRejectionWarning: Error: socket hang up Sep 04 17:24:05 volumio volumio[865]: at connResetException (internal/errors.js:607:14) Sep 04 17:24:05 volumio volumio[865]: at Socket.socketOnEnd (_http_client.js:493:23) Sep 04 17:24:05 volumio volumio[865]: at Socket.emit (events.js:327:22) Sep 04 17:24:05 volumio volumio[865]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 04 17:24:05 volumio volumio[865]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 04 17:24:05 volumio volumio[865]: (node:865) 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: 361) Sep 04 17:24:05 volumio volumio[865]: info: Connection to go-librespot Websocket closed Sep 04 17:24:08 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:24:08 volumio volumio[865]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 17:24:08 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 17:24:08 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 345. Sep 04 17:24:08 volumio systemd[1]: Stopped go-librespot Daemon. Sep 04 17:24:09 volumio systemd[1]: Started go-librespot Daemon. Sep 04 17:24:09 volumio go-librespot[11350]: Librespot-go daemon starting... Sep 04 17:24:09 volumio go-librespot[11350]: time="2024-09-04T17:24:09+08:00" level=info msg="generated new device id: 8d0e808570eeda94486942a7a3fe769a0a2fa4d1" Sep 04 17:24:09 volumio go-librespot[11350]: time="2024-09-04T17:24:09+08:00" level=debug msg="stored credentials not found" Sep 04 17:24:11 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:24:11 volumio go-librespot[11350]: time="2024-09-04T17:24:11+08:00" level=debug msg="new websocket client" Sep 04 17:24:11 volumio volumio[865]: info: Connection to go-librespot Websocket established Sep 04 17:24:14 volumio volumio[865]: info: Getting Spotify volume Sep 04 17:24:14 volumio volumio[865]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Sep 04 17:24:14 volumio volumio[865]: info: CoreCommandRouter::volumioGetState Sep 04 17:24:14 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:14 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:16 volumio go-librespot[11350]: time="2024-09-04T17:24:16+08:00" level=debug msg="obtained new client token: AADrL7pqmTscSEEbYjTm2r9nBI+q2qbX24HJkr4PosCHPPkXJqsPyvYVemeGIxxajLw5X7R57nsVYXQYYsZwpJABrJMgvjoHRztNFxR++Hy5kvDld7apokY2hc2V/LNsGxqjFJy/LpQW6qc0sdWgUHGqtQSmYNk6mSEa9TolSSZKGzPuU35id1+io2RaxRZftkFiSUF1XybPzFNF9qPFg8d9spb8zJgYdMazMa1knp82KVIO5gtsjxqmqn+N4dcg" Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::volumioPlay Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::play index undefined Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::startPlaybackTimer Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: info: ControllerMpd::resume Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand play Sep 04 17:24:21 volumio volumio[865]: info: Sep 04 17:24:21 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:21 volumio volumio[865]: info: sendMpdCommand play took 226 milliseconds Sep 04 17:24:21 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:21 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 Sep 04 17:24:21 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 Sep 04 17:24:21 volumio volumio[865]: info: Sep 04 17:24:21 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:21 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:21 volumio volumio[865]: info: Sep 04 17:24:21 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:21 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:21 volumio volumio[865]: info: sendMpdCommand status took 6 milliseconds Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:21 volumio volumio[865]: info: sendMpdCommand status took 5 milliseconds Sep 04 17:24:21 volumio volumio[865]: info: sendMpdCommand status took 4 milliseconds Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:21 volumio volumio[865]: info: sendMpdCommand playlistinfo took 3 milliseconds Sep 04 17:24:21 volumio volumio[865]: info: sendMpdCommand playlistinfo took 2 milliseconds Sep 04 17:24:21 volumio volumio[865]: info: sendMpdCommand playlistinfo took 1 milliseconds Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:21 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:21 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":279248,"duration":308,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"752 Kbps","isStreaming":false,"title":"我终于失去了你","artist":"孙露","album":"爱人别走","uri":"USB/288016118015E65A/kgmusic/孙露 - 我终于失去了你.flac","trackType":"flac"} Sep 04 17:24:21 volumio volumio[865]: verbose: CURRENT POSITION 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus pause Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:21 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":279248,"duration":308,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"752 Kbps","isStreaming":false,"title":"我终于失去了你","artist":"孙露","album":"爱人别走","uri":"USB/288016118015E65A/kgmusic/孙露 - 我终于失去了你.flac","trackType":"flac"} Sep 04 17:24:21 volumio volumio[865]: verbose: CURRENT POSITION 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:21 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:21 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":279248,"duration":308,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"752 Kbps","isStreaming":false,"title":"我终于失去了你","artist":"孙露","album":"爱人别走","uri":"USB/288016118015E65A/kgmusic/孙露 - 我终于失去了你.flac","trackType":"flac"} Sep 04 17:24:21 volumio volumio[865]: verbose: CURRENT POSITION 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:21 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:21 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:21 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:21 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:21 volumio volumio[865]: info: ------------------------------ 37ms Sep 04 17:24:21 volumio volumio[865]: info: ------------------------------ 36ms Sep 04 17:24:21 volumio volumio[865]: info: ------------------------------ 35ms Sep 04 17:24:21 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:21 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:21 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:21 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:21 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:27 volumio go-librespot[11350]: time="2024-09-04T17:24:27+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Sep 04 17:24:32 volumio go-librespot[11350]: time="2024-09-04T17:24:32+08:00" level=debug msg="completed keyexchange" Sep 04 17:24:33 volumio go-librespot[11350]: time="2024-09-04T17:24:33+08:00" level=debug msg="completed challenge" Sep 04 17:24:33 volumio go-librespot[11350]: time="2024-09-04T17:24:33+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" Sep 04 17:24:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 17:24:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 17:24:33 volumio volumio[865]: (node:865) UnhandledPromiseRejectionWarning: Error: socket hang up Sep 04 17:24:33 volumio volumio[865]: at connResetException (internal/errors.js:607:14) Sep 04 17:24:33 volumio volumio[865]: at Socket.socketOnEnd (_http_client.js:493:23) Sep 04 17:24:33 volumio volumio[865]: at Socket.emit (events.js:327:22) Sep 04 17:24:33 volumio volumio[865]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 04 17:24:33 volumio volumio[865]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 04 17:24:33 volumio volumio[865]: (node:865) 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: 362) Sep 04 17:24:33 volumio volumio[865]: info: Connection to go-librespot Websocket closed Sep 04 17:24:36 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:24:36 volumio volumio[865]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 17:24:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 17:24:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 346. Sep 04 17:24:36 volumio systemd[1]: Stopped go-librespot Daemon. Sep 04 17:24:36 volumio systemd[1]: Started go-librespot Daemon. Sep 04 17:24:36 volumio go-librespot[11365]: Librespot-go daemon starting... Sep 04 17:24:36 volumio go-librespot[11365]: time="2024-09-04T17:24:36+08:00" level=info msg="generated new device id: d7e211fbd25fafcf019c5fedf221fd5333335363" Sep 04 17:24:36 volumio go-librespot[11365]: time="2024-09-04T17:24:36+08:00" level=debug msg="stored credentials not found" Sep 04 17:24:39 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:24:39 volumio go-librespot[11365]: time="2024-09-04T17:24:39+08:00" level=debug msg="new websocket client" Sep 04 17:24:39 volumio volumio[865]: info: Connection to go-librespot Websocket established Sep 04 17:24:42 volumio volumio[865]: info: Getting Spotify volume Sep 04 17:24:42 volumio volumio[865]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Sep 04 17:24:42 volumio volumio[865]: info: CoreCommandRouter::volumioGetState Sep 04 17:24:42 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:42 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:44 volumio go-librespot[11365]: time="2024-09-04T17:24:44+08:00" level=debug msg="obtained new client token: AAAGaZGQ/cXaBS5MkUOb9QjxMz+rqiGOJkkbAypP0MDiSQMrRhIAoWnOl7StVLfftzgdhzRRBQ9LuumaUIpMSTtKd4fDhT+nn22E9D7Fii5SEg2O7clnJ19xA9nuG1QC8A2Mf+fO5K9eZpV4SmJYOAxqRdK9K0EbfnwRS1lXvwNfxW6yDj/EfFfeRRlo0wlhQ2y0yW4kMV5JXx6j+/i/Z1Jl8QBZj+WEvfU1GJQ46bL/aGhx9X+l5+zTmPqyxXS6" Sep 04 17:24:45 volumio volumio[865]: info: CorePlayQueue::getTrack 227 Sep 04 17:24:45 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:45 volumio volumio[865]: info: Prefetching next song Sep 04 17:24:45 volumio volumio[865]: info: DOING PREFETCH IN MPD Sep 04 17:24:45 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/kgmusic/孙露 - 半梦半醒之间.flac" Sep 04 17:24:45 volumio volumio[865]: info: Sep 04 17:24:45 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:45 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:45 volumio volumio[865]: info: sendMpdCommand add "USB/288016118015E65A/kgmusic/孙露 - 半梦半醒之间.flac" took 2 milliseconds Sep 04 17:24:45 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand consume 1 Sep 04 17:24:45 volumio volumio[865]: info: Sep 04 17:24:45 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:45 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:45 volumio volumio[865]: info: Sep 04 17:24:45 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:45 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:45 volumio volumio[865]: info: ------------------------------ 5ms Sep 04 17:24:45 volumio volumio[865]: info: sendMpdCommand consume 1 took 3 milliseconds Sep 04 17:24:45 volumio volumio[865]: info: ------------------------------ 3ms Sep 04 17:24:45 volumio volumio[865]: info: ------------------------------ 3ms Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::startPlaybackTimer Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: info: Sep 04 17:24:49 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:49 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:49 volumio volumio[865]: info: Sep 04 17:24:49 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:49 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:49 volumio volumio[865]: info: Sep 04 17:24:49 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:49 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:49 volumio volumio[865]: info: Sep 04 17:24:49 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:49 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:49 volumio volumio[865]: info: ------------------------------ 3ms Sep 04 17:24:49 volumio volumio[865]: info: sendMpdCommand status took 2 milliseconds Sep 04 17:24:49 volumio volumio[865]: info: ------------------------------ 2ms Sep 04 17:24:49 volumio volumio[865]: info: sendMpdCommand status took 1 milliseconds Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:49 volumio volumio[865]: info: Sep 04 17:24:49 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:49 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:49 volumio volumio[865]: info: Sep 04 17:24:49 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:49 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:49 volumio volumio[865]: info: sendMpdCommand playlistinfo took 6 milliseconds Sep 04 17:24:49 volumio volumio[865]: info: sendMpdCommand playlistinfo took 6 milliseconds Sep 04 17:24:49 volumio volumio[865]: info: ------------------------------ 6ms Sep 04 17:24:49 volumio volumio[865]: info: sendMpdCommand status took 2 milliseconds Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:49 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":22,"duration":235,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"234 Kbps","isStreaming":false,"title":"半梦半醒之间","artist":"孙露","album":"爱人别走","uri":"USB/288016118015E65A/kgmusic/孙露 - 半梦半醒之间.flac","trackType":"flac"} Sep 04 17:24:49 volumio volumio[865]: verbose: CURRENT POSITION 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:49 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:49 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":22,"duration":235,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"234 Kbps","isStreaming":false,"title":"半梦半醒之间","artist":"孙露","album":"爱人别走","uri":"USB/288016118015E65A/kgmusic/孙露 - 半梦半醒之间.flac","trackType":"flac"} Sep 04 17:24:49 volumio volumio[865]: verbose: CURRENT POSITION 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:49 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:49 volumio volumio[865]: info: ------------------------------ 34ms Sep 04 17:24:49 volumio volumio[865]: info: ------------------------------ 34ms Sep 04 17:24:49 volumio volumio[865]: info: sendMpdCommand playlistinfo took 26 milliseconds Sep 04 17:24:49 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:49 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":22,"duration":235,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"234 Kbps","isStreaming":false,"title":"半梦半醒之间","artist":"孙露","album":"爱人别走","uri":"USB/288016118015E65A/kgmusic/孙露 - 半梦半醒之间.flac","trackType":"flac"} Sep 04 17:24:49 volumio volumio[865]: verbose: CURRENT POSITION 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:49 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:49 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:49 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:49 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:49 volumio volumio[865]: info: ------------------------------ 50ms Sep 04 17:24:49 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:49 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:49 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:49 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:49 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:49 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:50 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:50 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:50 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:24:50 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:50 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioNext Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::next Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::stPlaybackTimer Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::updateTrackBlock Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrackBlock Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::serviceStop Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 228 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::serviceStop Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::stop Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand stop Sep 04 17:24:51 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 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand stop took 11 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::play index undefined Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::startPlaybackTimer Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::updateTrackBlock Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrackBlock Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 5 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand stop took 2 milliseconds Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand clear Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:51 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand playlistinfo took 34 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand clear took 34 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 3 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 2 milliseconds Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac" Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"半梦半醒之间","artist":"孙露","album":"爱人别走","uri":"USB/288016118015E65A/kgmusic/孙露 - 半梦半醒之间.flac","trackType":"flac"} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: No code Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: 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} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: No code Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: 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} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: No code Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 108ms Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 73ms Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 73ms Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:51 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:51 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:51 volumio volumio[865]: error: updateQueue error: null Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:51 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 82ms Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand add "USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac" took 80 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 6ms Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 4ms Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand play Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:51 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:24:51 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: info: touch_display: Setting screensaver timeout to 15 seconds. Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 49ms Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand play took 47 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 47ms Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 46ms Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Sep 04 17:24:51 volumio volumio[865]: info: touch_display: Setting screensaver timeout to 15 seconds. Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 219 milliseconds Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: Sep 04 17:24:51 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:24:51 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 Sep 04 17:24:51 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 Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 225 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 225 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand playlistinfo took 11 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 8 milliseconds Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":310,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"蓝色街灯","artist":"黎明","album":"爱得太傻48首精选[2CD+VCD]","uri":"USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac","trackType":"flac"} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 235ms Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 9 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand status took 5 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand playlistinfo took 3 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand playlistinfo took 3 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand playlistinfo took 3 milliseconds Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":310,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"574 Kbps","isStreaming":false,"title":"蓝色街灯","artist":"黎明","album":"爱得太傻48首精选[2CD+VCD]","uri":"USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac","trackType":"flac"} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:51 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":310,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"574 Kbps","isStreaming":false,"title":"蓝色街灯","artist":"黎明","album":"爱得太傻48首精选[2CD+VCD]","uri":"USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac","trackType":"flac"} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:51 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":310,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"574 Kbps","isStreaming":false,"title":"蓝色街灯","artist":"黎明","album":"爱得太傻48首精选[2CD+VCD]","uri":"USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac","trackType":"flac"} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:51 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 276ms Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 273ms Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 58ms Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand playlistinfo took 53 milliseconds Sep 04 17:24:51 volumio volumio[865]: info: sendMpdCommand playlistinfo took 53 milliseconds Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:51 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":310,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"574 Kbps","isStreaming":false,"title":"蓝色街灯","artist":"黎明","album":"爱得太傻48首精选[2CD+VCD]","uri":"USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac","trackType":"flac"} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:51 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":310,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"574 Kbps","isStreaming":false,"title":"蓝色街灯","artist":"黎明","album":"爱得太傻48首精选[2CD+VCD]","uri":"USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac","trackType":"flac"} Sep 04 17:24:51 volumio volumio[865]: verbose: CURRENT POSITION 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:24:51 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:24:51 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:24:51 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 124ms Sep 04 17:24:51 volumio volumio[865]: info: ------------------------------ 124ms Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:51 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:24:53 volumio go-librespot[11365]: time="2024-09-04T17:24: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Sep 04 17:24:59 volumio go-librespot[11365]: time="2024-09-04T17:24:59+08:00" level=debug msg="completed keyexchange" Sep 04 17:24:59 volumio go-librespot[11365]: time="2024-09-04T17:24:59+08:00" level=debug msg="completed challenge" Sep 04 17:25:00 volumio go-librespot[11365]: time="2024-09-04T17:25: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" Sep 04 17:25:00 volumio volumio[865]: (node:865) UnhandledPromiseRejectionWarning: Error: socket hang up Sep 04 17:25:00 volumio volumio[865]: at connResetException (internal/errors.js:607:14) Sep 04 17:25:00 volumio volumio[865]: at Socket.socketOnEnd (_http_client.js:493:23) Sep 04 17:25:00 volumio volumio[865]: at Socket.emit (events.js:327:22) Sep 04 17:25:00 volumio volumio[865]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 04 17:25:00 volumio volumio[865]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 04 17:25:00 volumio volumio[865]: (node:865) 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: 363) Sep 04 17:25:00 volumio volumio[865]: info: Connection to go-librespot Websocket closed Sep 04 17:25:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 17:25:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 17:25:03 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:25:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 17:25:03 volumio volumio[865]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 17:25:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 347. Sep 04 17:25:03 volumio systemd[1]: Stopped go-librespot Daemon. Sep 04 17:25:03 volumio systemd[1]: Started go-librespot Daemon. Sep 04 17:25:03 volumio go-librespot[11419]: Librespot-go daemon starting... Sep 04 17:25:03 volumio go-librespot[11419]: time="2024-09-04T17:25:03+08:00" level=info msg="generated new device id: de86021b0d13cc7c97bf92684cb101d4279fc680" Sep 04 17:25:03 volumio go-librespot[11419]: time="2024-09-04T17:25:03+08:00" level=debug msg="stored credentials not found" Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioNext Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::next Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::stPlaybackTimer Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::updateTrackBlock Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrackBlock Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::serviceStop Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 229 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::serviceStop Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::stop Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand stop Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 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 Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand stop took 14 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::play index undefined Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::startPlaybackTimer Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::updateTrackBlock Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrackBlock Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 4 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand stop took 2 milliseconds Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand clear Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:05 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand playlistinfo took 49 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand clear took 48 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 10 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 7 milliseconds Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac" Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"蓝色街灯","artist":"黎明","album":"爱得太傻48首精选[2CD+VCD]","uri":"USB/288016118015E65A/kgmusic/黎明 - 蓝色街灯.flac","trackType":"flac"} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: No code Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: 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} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: No code Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: 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} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: No code Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 104ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 61ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 59ms Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:05 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:05 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:05 volumio volumio[865]: info: touch_display: Setting screensaver timeout to 15 seconds. Sep 04 17:25:05 volumio volumio[865]: error: updateQueue error: null Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:05 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 85ms Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand add "USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac" took 77 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 29ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 27ms Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand play Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:05 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:05 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 47ms Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand play took 46 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 46ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 45ms Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 232 milliseconds Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 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 Sep 04 17:25:05 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 Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 233 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 231 milliseconds Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: Sep 04 17:25:05 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand playlistinfo took 5 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 4 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand playlistinfo took 3 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand playlistinfo took 3 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 2 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand status took 1 milliseconds Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":286,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"做你心上人","artist":"孙露","album":"爱的寂寞","uri":"USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac","trackType":"flac"} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":137,"duration":286,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"307 Kbps","isStreaming":false,"title":"做你心上人","artist":"孙露","album":"爱的寂寞","uri":"USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac","trackType":"flac"} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:05 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":205,"duration":286,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"307 Kbps","isStreaming":false,"title":"做你心上人","artist":"孙露","album":"爱的寂寞","uri":"USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac","trackType":"flac"} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:05 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 256ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 275ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 274ms Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand playlistinfo took 39 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand playlistinfo took 40 milliseconds Sep 04 17:25:05 volumio volumio[865]: info: sendMpdCommand playlistinfo took 41 milliseconds Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:05 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":286,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"308 Kbps","isStreaming":false,"title":"做你心上人","artist":"孙露","album":"爱的寂寞","uri":"USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac","trackType":"flac"} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:05 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":286,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"308 Kbps","isStreaming":false,"title":"做你心上人","artist":"孙露","album":"爱的寂寞","uri":"USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac","trackType":"flac"} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:05 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":286,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"308 Kbps","isStreaming":false,"title":"做你心上人","artist":"孙露","album":"爱的寂寞","uri":"USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac","trackType":"flac"} Sep 04 17:25:05 volumio volumio[865]: verbose: CURRENT POSITION 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:05 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:05 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:05 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 106ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 105ms Sep 04 17:25:05 volumio volumio[865]: info: ------------------------------ 106ms Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:05 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:06 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:25:06 volumio go-librespot[11419]: time="2024-09-04T17:25:06+08:00" level=debug msg="new websocket client" Sep 04 17:25:06 volumio volumio[865]: info: Connection to go-librespot Websocket established Sep 04 17:25:09 volumio volumio[865]: info: Getting Spotify volume Sep 04 17:25:09 volumio volumio[865]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Sep 04 17:25:09 volumio volumio[865]: info: CoreCommandRouter::volumioGetState Sep 04 17:25:09 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:09 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:09 volumio go-librespot[11419]: time="2024-09-04T17:25:09+08:00" level=debug msg="obtained new client token: AAA7EocX28itz+GYVsG44gM4bOhK8wy/0NmtRiNwuTY0W9cMcB4G9mtUWpFbEWqWf7O0MDSmpb0uk5M7HSAshOD3LxxKneDIJU/JyvlbH9wULUa98s+aGevaqr1Wv8+gXXvvLBjSN4X47XR7tcUiewZ1vWGZjc8jZfi4ZNjH5EQgxcEvkfVdQ8CBBgAu39bPqfpvzyS+YrTEAUVal6S79yQxSATRkh2d4j2mYOkWb9MvK3babacHhVe6uhNHszAG" Sep 04 17:25:16 volumio go-librespot[11419]: time="2024-09-04T17:25:16+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]" Sep 04 17:25:21 volumio go-librespot[11419]: time="2024-09-04T17:25:21+08:00" level=debug msg="completed keyexchange" Sep 04 17:25:22 volumio go-librespot[11419]: time="2024-09-04T17:25:22+08:00" level=debug msg="completed challenge" Sep 04 17:25:22 volumio go-librespot[11419]: time="2024-09-04T17:25:22+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" Sep 04 17:25:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 17:25:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 17:25:22 volumio volumio[865]: (node:865) UnhandledPromiseRejectionWarning: Error: socket hang up Sep 04 17:25:22 volumio volumio[865]: at connResetException (internal/errors.js:607:14) Sep 04 17:25:22 volumio volumio[865]: at Socket.socketOnEnd (_http_client.js:493:23) Sep 04 17:25:22 volumio volumio[865]: at Socket.emit (events.js:327:22) Sep 04 17:25:22 volumio volumio[865]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 04 17:25:22 volumio volumio[865]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 04 17:25:22 volumio volumio[865]: (node:865) 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: 364) Sep 04 17:25:22 volumio volumio[865]: info: Connection to go-librespot Websocket closed Sep 04 17:25:25 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:25:25 volumio volumio[865]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 17:25:25 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 17:25:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 348. Sep 04 17:25:25 volumio systemd[1]: Stopped go-librespot Daemon. Sep 04 17:25:25 volumio systemd[1]: Started go-librespot Daemon. Sep 04 17:25:25 volumio go-librespot[11433]: Librespot-go daemon starting... Sep 04 17:25:26 volumio go-librespot[11433]: time="2024-09-04T17:25:26+08:00" level=info msg="generated new device id: 95aa7e0087d5eb7c1deffc2d0f776c266120c5d3" Sep 04 17:25:26 volumio go-librespot[11433]: time="2024-09-04T17:25:26+08:00" level=debug msg="stored credentials not found" Sep 04 17:25:28 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:25:28 volumio go-librespot[11433]: time="2024-09-04T17:25:28+08:00" level=debug msg="new websocket client" Sep 04 17:25:28 volumio volumio[865]: info: Connection to go-librespot Websocket established Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPlay Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::play index 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::stop Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::stPlaybackTimer Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::updateTrackBlock Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrackBlock Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::serviceStop Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 230 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::serviceStop Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::stop Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand stop Sep 04 17:25:30 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 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand stop took 38 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::play index undefined Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::startPlaybackTimer Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3 Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand stop Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 31 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand stop took 7 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 5 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 2 milliseconds Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand clear Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: info: touch_display: Setting screensaver timeout to 15 seconds. Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:30 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 4 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand clear took 5 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 5 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 4 milliseconds Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3" Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"做你心上人","artist":"孙露","album":"爱的寂寞","uri":"USB/288016118015E65A/kgmusic/孙露 - 做你心上的人.flac","trackType":"flac"} Sep 04 17:25:30 volumio volumio[865]: verbose: CURRENT POSITION 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState stateService stop Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: No code Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Sep 04 17:25:30 volumio volumio[865]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 61ms Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 36ms Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 34ms Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:30 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:30 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:30 volumio volumio[865]: error: updateQueue error: null Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:30 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 33ms Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand add "USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3" took 30 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 8ms Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 6ms Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand play Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:30 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces system playlist update Sep 04 17:25:30 volumio volumio[865]: info: Ignoring MPD Status Update Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 59ms Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand play took 56 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 55ms Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 53ms Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 194 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 195 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 194 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 1 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 2 milliseconds Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 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 Sep 04 17:25:30 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 Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":162,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"旧欢如梦","artist":"李克勤","album":"环球珍藏之最 Vol.2","uri":"USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3","trackType":"mp3"} Sep 04 17:25:30 volumio volumio[865]: verbose: CURRENT POSITION 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus stop Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 200ms Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: Sep 04 17:25:30 volumio volumio[865]: ---------------------------- MPD announces state update: player Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::getState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand status Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 4 milliseconds Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":434,"duration":162,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"旧欢如梦","artist":"李克勤","album":"环球珍藏之最 Vol.2","uri":"USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3","trackType":"mp3"} Sep 04 17:25:30 volumio volumio[865]: verbose: CURRENT POSITION 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:30 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 208ms Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 14 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 16 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 14 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand status took 14 milliseconds Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseState Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":445,"duration":162,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"旧欢如梦","artist":"李克勤","album":"环球珍藏之最 Vol.2","uri":"USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3","trackType":"mp3"} Sep 04 17:25:30 volumio volumio[865]: verbose: CURRENT POSITION 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:30 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":162,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"旧欢如梦","artist":"李克勤","album":"环球珍藏之最 Vol.2","uri":"USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3","trackType":"mp3"} Sep 04 17:25:30 volumio volumio[865]: verbose: CURRENT POSITION 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:30 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 234ms Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 44ms Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 40 milliseconds Sep 04 17:25:30 volumio volumio[865]: info: sendMpdCommand playlistinfo took 40 milliseconds Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: verbose: ControllerMpd::parseTrackInfo Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":162,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"旧欢如梦","artist":"李克勤","album":"环球珍藏之最 Vol.2","uri":"USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3","trackType":"mp3"} Sep 04 17:25:30 volumio volumio[865]: verbose: CURRENT POSITION 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:30 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: ControllerMpd::pushState Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::servicePushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: verbose: STATE SERVICE {"status":"play","position":0,"seek":731,"duration":162,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"旧欢如梦","artist":"李克勤","album":"环球珍藏之最 Vol.2","uri":"USB/288016118015E65A/kgmusic/李克勤 - 旧欢如梦.mp3","trackType":"mp3"} Sep 04 17:25:30 volumio volumio[865]: verbose: CURRENT POSITION 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState stateService play Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::syncState currentStatus play Sep 04 17:25:30 volumio volumio[865]: info: Received an update from plugin. extracting info from payload Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: CoreStateMachine::pushState Sep 04 17:25:30 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:30 volumio volumio[865]: info: CoreCommandRouter::volumioPushState Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 78ms Sep 04 17:25:30 volumio volumio[865]: info: ------------------------------ 77ms Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:30 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:31 volumio volumio[865]: info: Getting Spotify volume Sep 04 17:25:31 volumio volumio[865]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Sep 04 17:25:31 volumio volumio[865]: info: CoreCommandRouter::volumioGetState Sep 04 17:25:31 volumio volumio[865]: info: CorePlayQueue::getTrack 235 Sep 04 17:25:31 volumio volumio[865]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Sep 04 17:25:36 volumio go-librespot[11433]: time="2024-09-04T17:25:36+08:00" level=debug msg="obtained new client token: AAA2npWUL7DkYNat9nZ5n41vWOjZbS7idvhezJVo2Ci3SKKyNUCXpY4qmwxRw/9zAKqz19k4RMNhxr+lAd4bwLRLfNWIDIKSnunxFSj+nGCvFr7XRaXT0LcSVqELT/HIABYgq0iM1PsTcr0f5xqRurXODOlxNZvkfJt/JKu/3Z62IgMc9e5CAtmPddqzl6nMEbmtLzwFPi0H6wyjvIUS7+CVql9ijwO9IdNgs7AIVqp4hq7Xm2SCWMCEEf/5Teca" Sep 04 17:25:43 volumio go-librespot[11433]: time="2024-09-04T17:25:43+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]" Sep 04 17:25:48 volumio go-librespot[11433]: time="2024-09-04T17:25:48+08:00" level=debug msg="completed keyexchange" Sep 04 17:25:49 volumio go-librespot[11433]: time="2024-09-04T17:25:49+08:00" level=debug msg="completed challenge" Sep 04 17:25:49 volumio go-librespot[11433]: time="2024-09-04T17:25:49+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" Sep 04 17:25:49 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Sep 04 17:25:49 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Sep 04 17:25:49 volumio volumio[865]: (node:865) UnhandledPromiseRejectionWarning: Error: socket hang up Sep 04 17:25:49 volumio volumio[865]: at connResetException (internal/errors.js:607:14) Sep 04 17:25:49 volumio volumio[865]: at Socket.socketOnEnd (_http_client.js:493:23) Sep 04 17:25:49 volumio volumio[865]: at Socket.emit (events.js:327:22) Sep 04 17:25:49 volumio volumio[865]: at endReadableNT (internal/streams/readable.js:1327:12) Sep 04 17:25:49 volumio volumio[865]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 04 17:25:49 volumio volumio[865]: (node:865) 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: 365) Sep 04 17:25:49 volumio volumio[865]: info: Connection to go-librespot Websocket closed Sep 04 17:25:52 volumio volumio[865]: info: Initializing connection to go-librespot Websocket Sep 04 17:25:52 volumio volumio[865]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Sep 04 17:25:52 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Sep 04 17:25:52 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 349. Sep 04 17:25:52 volumio systemd[1]: Stopped go-librespot Daemon. Sep 04 17:25:52 volumio systemd[1]: Started go-librespot Daemon. Sep 04 17:25:52 volumio go-librespot[11446]: Librespot-go daemon starting... Sep 04 17:25:52 volumio go-librespot[11446]: time="2024-09-04T17:25:52+08:00" level=info msg="generated new device id: 949ad86ab34db986f451d46f892cafb22501afb8" Sep 04 17:25:52 volumio go-librespot[11446]: time="2024-09-04T17:25:52+08:00" level=debug msg="stored credentials not found" Sep 04 17:25:53 volumio volumio[865]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 17:25:53 volumio volumio[865]: Error: connect ETIMEDOUT 157.240.0.18:80 Sep 04 17:25:53 volumio volumio[865]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Sep 04 17:25:53 volumio volumio[865]: errno: -110, Sep 04 17:25:53 volumio volumio[865]: code: 'ETIMEDOUT', Sep 04 17:25:53 volumio volumio[865]: syscall: 'connect', Sep 04 17:25:53 volumio volumio[865]: address: '157.240.0.18', Sep 04 17:25:53 volumio volumio[865]: port: 80 Sep 04 17:25:53 volumio volumio[865]: } Sep 04 17:25:53 volumio volumio[865]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 04 17:25:54 volumio sudo[11463]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-04 17:24 Sep 04 17:25:54 volumio sudo[11463]: 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"