-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Sat 2024-04-20 18:18:28 CST. -- Apr 20 18:17:00 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:17:00 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:00 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:17:00 volumio volumio[856]: (node:856) 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: 896) Apr 20 18:17:00 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14 Apr 20 18:17:00 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:17:00 volumio volumio[856]: info: CorePlayQueue::getTrack 5 Apr 20 18:17:00 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:01 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:01 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88. Apr 20 18:17:01 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:01 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:01 volumio go-librespot[3976]: Librespot-go daemon starting... Apr 20 18:17:01 volumio go-librespot[3976]: time="2024-04-20T18:17:01+08:00" level=info msg="generated new device id: 6f86bcdf2122f3d6a8759d9e43bdaeefb3de9735" Apr 20 18:17:01 volumio go-librespot[3976]: time="2024-04-20T18:17:01+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:02 volumio go-librespot[3976]: time="2024-04-20T18:17:02+08:00" level=debug msg="obtained new client token: AAAGuk/3CzE88l2Jegf8TpQE7Rl9v5Oevti0GlVjRRd45c06IHYiIirKv8jLP4gD18z/RBSAn6wUioQYlcukNZgF4KDGH04JYMs/yplWQ6HfCpMD7hLlXAk/nF9+27kZAMLjOjMehi3/NMIJrR6pget0XxKrf72QAMmPZVmW+I2Jt91BO7AK4qqD8F+4b5d8dDCOZBWzqf9awoLppWfzFcdE3L/dionEib9OpS4oAHmUiH7vun34UwiYvQE=" Apr 20 18:17:02 volumio go-librespot[3976]: time="2024-04-20T18:17:02+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 20 18:17:03 volumio go-librespot[3976]: time="2024-04-20T18:17:03+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:03 volumio go-librespot[3976]: time="2024-04-20T18:17:03+08:00" level=debug msg="completed challenge" Apr 20 18:17:03 volumio go-librespot[3976]: time="2024-04-20T18:17:03+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: TravelRestriction" Apr 20 18:17:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:04 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:04 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:07 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 89. Apr 20 18:17:07 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:07 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:07 volumio go-librespot[3995]: Librespot-go daemon starting... Apr 20 18:17:07 volumio go-librespot[3995]: time="2024-04-20T18:17:07+08:00" level=info msg="generated new device id: 6e0c4eb324c306edc76965fbfd183574b18b37b4" Apr 20 18:17:07 volumio go-librespot[3995]: time="2024-04-20T18:17:07+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:07 volumio go-librespot[3995]: time="2024-04-20T18:17:07+08:00" level=debug msg="obtained new client token: AAARtIlKZi3DbpMYpbXl/WOY13s5NSptkdeoB4/e12chquecu/Gkj8bFZL3aGJF63nsjjY38YK0gg5cDFSgiaFKBAgCRKTFSakJx+QXLfbrz+wjZTFDjYXkvuKH8haHqI21ce+DWG3FuciyDfto0jv4SYdhuz6CfD/a/Rfdswi4ZIiegolYdjjNnMa8d4DGpm5q1msIQTPG579Tu6FjFdJ3V+WzCeZ4bfo0F1LnlQrRl+Ff2kDvg61cRMeATWA==" Apr 20 18:17:07 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:07 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:17:07 volumio go-librespot[3995]: time="2024-04-20T18:17:07+08:00" level=debug msg="new websocket client" Apr 20 18:17:07 volumio go-librespot[3995]: time="2024-04-20T18:17:07+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:17:08 volumio go-librespot[3995]: time="2024-04-20T18:17:08+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:08 volumio go-librespot[3995]: time="2024-04-20T18:17:08+08:00" level=debug msg="completed challenge" Apr 20 18:17:09 volumio go-librespot[3995]: time="2024-04-20T18:17:09+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: TravelRestriction" Apr 20 18:17:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:09 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:17:10 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:17:10 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:10 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:17:10 volumio volumio[856]: (node:856) 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: 897) Apr 20 18:17:10 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14 Apr 20 18:17:10 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:17:10 volumio volumio[856]: info: CorePlayQueue::getTrack 5 Apr 20 18:17:10 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:12 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:12 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:12 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:12 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90. Apr 20 18:17:12 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:12 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:12 volumio go-librespot[4015]: Librespot-go daemon starting... Apr 20 18:17:12 volumio go-librespot[4015]: time="2024-04-20T18:17:12+08:00" level=info msg="generated new device id: b75aa61d321afae9fdb5ccf904ffaf3550513d55" Apr 20 18:17:12 volumio go-librespot[4015]: time="2024-04-20T18:17:12+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:12 volumio go-librespot[4015]: time="2024-04-20T18:17:12+08:00" level=debug msg="obtained new client token: AAAabVY/b81RctgOUrNainKQqbqG+6EG8ynXtwcADRD09NBpbNaUNTEjpr1Yigb9NbWONyXNo2JApVPHrQpBDXR02dQkb4oVYI8I+p7cEP8n5VbJGkF+5J+pTAmn29ev7Y5NiV990QBtk8KbVuUPLNEI4oWuqVTgIaguUkMo+agDowYeP+SCch2YU6b17iqU32W7T200l8vMFBGNZR6s6qf7MUyZn83ls7YTzUfnRoy4+Xd9Xm0f3UVRwgypyg==" Apr 20 18:17:13 volumio go-librespot[4015]: time="2024-04-20T18:17:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:17:13 volumio go-librespot[4015]: time="2024-04-20T18:17:13+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:14 volumio go-librespot[4015]: time="2024-04-20T18:17:14+08:00" level=debug msg="completed challenge" Apr 20 18:17:14 volumio go-librespot[4015]: time="2024-04-20T18:17:14+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: TravelRestriction" Apr 20 18:17:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:15 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:15 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:16 volumio volumio[856]: error: [yt-cast-receiver] (YouTube Music) Error occurred in SendMessageTask: Apr 20 18:17:16 volumio volumio[856]: LoungeScreenDisconnected { Apr 20 18:17:16 volumio volumio[856]: AID: null, Apr 20 18:17:16 volumio volumio[856]: name: 'loungeScreenDisconnected', Apr 20 18:17:16 volumio volumio[856]: payload: {} Apr 20 18:17:16 volumio volumio[856]: } Apr 20 18:17:16 volumio volumio[856]: (IncompleteAPIDataError) Missing data required to construct query string from bind params Apr 20 18:17:16 volumio volumio[856]: Error info: { missing: [ 'loungeIdToken', 'SID', 'gsessionid' ] } Apr 20 18:17:16 volumio volumio[856]: Stack trace: Apr 20 18:17:16 volumio volumio[856]: IncompleteAPIDataError: Missing data required to construct query string from bind params Apr 20 18:17:16 volumio volumio[856]: at BindParams.toQueryString (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/BindParams.js:120:19) Apr 20 18:17:16 volumio volumio[856]: at Session._Session_doSendMessage (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:492:103) Apr 20 18:17:16 volumio volumio[856]: at SendMessageTask.run (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:552:71) Apr 20 18:17:16 volumio volumio[856]: at AsyncTaskQueue.start (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/utils/AsyncTaskQueue.js:51:36) Apr 20 18:17:16 volumio volumio[856]: at Session.end (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:237:71) Apr 20 18:17:16 volumio volumio[856]: at runMicrotasks () Apr 20 18:17:16 volumio volumio[856]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:17:16 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'removeAllListeners' of undefined Apr 20 18:17:16 volumio volumio[856]: at Session._Session_refreshLoungeToken (/data/plugins/music_service/ytcr/node_modules/yt-cast-receiver/dist/cjs/lib/app/Session.js:372:16) Apr 20 18:17:16 volumio volumio[856]: at runMicrotasks () Apr 20 18:17:16 volumio volumio[856]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 20 18:17:16 volumio volumio[856]: (node:856) 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: 899) Apr 20 18:17:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91. Apr 20 18:17:17 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:17 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:17 volumio go-librespot[4034]: Librespot-go daemon starting... Apr 20 18:17:17 volumio go-librespot[4034]: time="2024-04-20T18:17:17+08:00" level=info msg="generated new device id: cf07bcf9b93d54253004c1d936ac0521b6a7bc75" Apr 20 18:17:17 volumio go-librespot[4034]: time="2024-04-20T18:17:17+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:17 volumio go-librespot[4034]: time="2024-04-20T18:17:17+08:00" level=debug msg="obtained new client token: AADnmjOoooO7m6og3ZF87dAnprEgbN51SG6IbDE7A1GmQeaYqs9FbA/gMxBI2VCExKpz2YNYC0y4tNCMxex4h1NbIT0TlgyjTRd95FZ0/85PaGSSQKF8mYTccrqDpTUvV3PJii+sZ0HoVpaON96Go1lHXks5C28X5jV/+R3i2eyFgWxVF9KZ/n9B3izHNnKDcxvSax0noIztlj7gOHYFhiE9V0vcU2tPTgnSPU+/LKD1qSxJhl8p2LWuYSwmJA==" Apr 20 18:17:18 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:18 volumio go-librespot[4034]: time="2024-04-20T18:17:18+08:00" level=debug msg="new websocket client" Apr 20 18:17:18 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:17:18 volumio go-librespot[4034]: time="2024-04-20T18:17:18+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 20 18:17:18 volumio go-librespot[4034]: time="2024-04-20T18:17:18+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:18 volumio go-librespot[4034]: time="2024-04-20T18:17:18+08:00" level=debug msg="completed challenge" Apr 20 18:17:19 volumio go-librespot[4034]: time="2024-04-20T18:17:19+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 20 18:17:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:19 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:17:21 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:17:21 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:21 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:17:21 volumio volumio[856]: (node:856) 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: 900) Apr 20 18:17:21 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14 Apr 20 18:17:21 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:17:21 volumio volumio[856]: info: CorePlayQueue::getTrack 5 Apr 20 18:17:21 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:22 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92. Apr 20 18:17:22 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:22 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:22 volumio go-librespot[4054]: Librespot-go daemon starting... Apr 20 18:17:22 volumio go-librespot[4054]: time="2024-04-20T18:17:22+08:00" level=info msg="generated new device id: a60173e185b6746cf0344ef226c8f7323e6cbc25" Apr 20 18:17:22 volumio go-librespot[4054]: time="2024-04-20T18:17:22+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioNext Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::next Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::stPlaybackTimer Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::updateTrackBlock Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrackBlock Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 5 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::serviceStop Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 5 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::serviceStop Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::stop Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand stop Apr 20 18:17:22 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand stop took 13 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::play index undefined Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::startPlaybackTimer Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::clearAddPlayTracks USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::updateTrackBlock Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrackBlock Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 8 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand stop took 2 milliseconds Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand clear Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:17:22 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand playlistinfo took 54 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand clear took 54 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 53 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 51 milliseconds Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand add "USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav" Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: 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/____U__/1.孙露WAV无损206首/003.爱人.wav","trackType":"wav"} Apr 20 18:17:22 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: No code Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 20 18:17:22 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: No code Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 20 18:17:22 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: No code Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 151ms Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 140ms Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 139ms Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:17:22 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:17:22 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:17:22 volumio volumio[856]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 20 18:17:22 volumio volumio[856]: error: updateQueue error: null Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:17:22 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 137ms Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand add "USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav" took 134 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 13ms Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 5ms Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand play Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:17:22 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:17:22 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 132ms Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand play took 131 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 118ms Apr 20 18:17:22 volumio volumio[856]: info: ------------------------------ 115ms Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio go-librespot[4054]: time="2024-04-20T18:17:22+08:00" level=debug msg="obtained new client token: AAAn5siV3HiRdYy35dE3t3pcKe35Fe8/fe2kDrbttfdDUlzgohHSQnFezvYzW1bcaI7SegjfdrkXcIh5UVX7YZzMu3DgHbtI7DMzDdfz3+wB1RC+QC2K+61rYYYgZ62kfp2mgpsTp33xaEgoGSrokk/rexAI4uFbGZYti3z3DBf4Y8cTKMzIJ1oI1zVMIN+hZv67Rc6aAt/frfrCBnCMTAdXgahkDzxaA/S9BLWkG+4TXsl5Ahruj1HJvdQjtA==" Apr 20 18:17:22 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Apr 20 18:17:22 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 142 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 141 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 139 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: info: Apr 20 18:17:22 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 3 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand playlistinfo took 4 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 3 milliseconds Apr 20 18:17:22 volumio volumio[856]: info: sendMpdCommand status took 2 milliseconds Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:17:22 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:17:22 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":434,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:17:22 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:17:22 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":434,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:17:22 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:17:22 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:22 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:22 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:22 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:23 volumio volumio[856]: info: ------------------------------ 171ms Apr 20 18:17:23 volumio volumio[856]: info: ------------------------------ 186ms Apr 20 18:17:23 volumio volumio[856]: info: ------------------------------ 185ms Apr 20 18:17:23 volumio volumio[856]: info: sendMpdCommand playlistinfo took 44 milliseconds Apr 20 18:17:23 volumio volumio[856]: info: sendMpdCommand playlistinfo took 43 milliseconds Apr 20 18:17:23 volumio volumio[856]: info: sendMpdCommand playlistinfo took 43 milliseconds Apr 20 18:17:23 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:17:23 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:17:23 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:17:23 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:17:23 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:17:23 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:23 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:17:23 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:17:23 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:23 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:17:23 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:17:23 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:23 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:17:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:23 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:17:23 volumio volumio[856]: info: ------------------------------ 126ms Apr 20 18:17:23 volumio volumio[856]: info: ------------------------------ 123ms Apr 20 18:17:23 volumio volumio[856]: info: ------------------------------ 124ms Apr 20 18:17:23 volumio go-librespot[4054]: time="2024-04-20T18:17:23+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:23 volumio go-librespot[4054]: time="2024-04-20T18:17:23+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:24 volumio go-librespot[4054]: time="2024-04-20T18:17:24+08:00" level=debug msg="completed challenge" Apr 20 18:17:24 volumio go-librespot[4054]: time="2024-04-20T18:17:24+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: TravelRestriction" Apr 20 18:17:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:25 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:25 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. Apr 20 18:17:27 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:27 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:27 volumio go-librespot[4092]: Librespot-go daemon starting... Apr 20 18:17:27 volumio go-librespot[4092]: time="2024-04-20T18:17:27+08:00" level=info msg="generated new device id: cae1db1ed8161c324832e6eba6cfe0d68d8befa6" Apr 20 18:17:27 volumio go-librespot[4092]: time="2024-04-20T18:17:27+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:28 volumio go-librespot[4092]: time="2024-04-20T18:17:28+08:00" level=debug msg="obtained new client token: AABQ+XTBBM7tVPli9kjRJdgSNnQISegwJHPNMqMsjcuqplhzQbXjDomJdGDfW+hX2BzNLFzakQszQVEF6KOmy0P72R5Hp1LLpugmmzGGot5qJ11H285XHqiyL4Ucusede3PtArHi9sIRjyeY4Va1AcWZ1u6dq/LF4Dc//toiGeTkwCZn5JajPp0EGhCd4tvCXlLiS7kYuuo7p864EPFpaCh87azazszkU3jVQqAwMsaqmDGDuk8W8+zlvfY06g==" Apr 20 18:17:28 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:28 volumio go-librespot[4092]: time="2024-04-20T18:17:28+08:00" level=debug msg="new websocket client" Apr 20 18:17:28 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:17:28 volumio go-librespot[4092]: time="2024-04-20T18:17:28+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:17:28 volumio go-librespot[4092]: time="2024-04-20T18:17:28+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:29 volumio go-librespot[4092]: time="2024-04-20T18:17:29+08:00" level=debug msg="completed challenge" Apr 20 18:17:29 volumio go-librespot[4092]: time="2024-04-20T18:17:29+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 20 18:17:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:29 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:17:31 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:17:31 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:31 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:17:31 volumio volumio[856]: (node:856) 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: 901) Apr 20 18:17:31 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14 Apr 20 18:17:31 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:17:31 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:31 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:32 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:32 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 94. Apr 20 18:17:32 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:32 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:32 volumio go-librespot[4151]: Librespot-go daemon starting... Apr 20 18:17:32 volumio go-librespot[4151]: time="2024-04-20T18:17:32+08:00" level=info msg="generated new device id: 8d4b03c51b00e865ee743d6e69e7132a9cddff03" Apr 20 18:17:32 volumio go-librespot[4151]: time="2024-04-20T18:17:32+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:33 volumio go-librespot[4151]: time="2024-04-20T18:17:33+08:00" level=debug msg="obtained new client token: AACSs1aMaN9EI9e1HHIpztVi2iQdKSM+lK1QB4iTm/6dJ00IvXlN8yyyomSdOEs6bFbnmYVPTiP+xbR6eEgcOFJgwk5K14x8Y4soD/MBOhhjhiR0DjgV3pEClYYqTiJQznfmW34hr5Fd0jXnBb588ECABi92cNXcJya30vAKuBHKyjiBoHe5Vv+6J9ayNO/+/yl3lh5E0bmW2P5yJkIOlBZ6Ffx5MzGM7zIcgz316DZxj/BIRAx+zE8hRPE=" Apr 20 18:17:33 volumio go-librespot[4151]: time="2024-04-20T18:17:33+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 20 18:17:34 volumio go-librespot[4151]: time="2024-04-20T18:17:34+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:34 volumio go-librespot[4151]: time="2024-04-20T18:17:34+08:00" level=debug msg="completed challenge" Apr 20 18:17:34 volumio go-librespot[4151]: time="2024-04-20T18:17:34+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: TravelRestriction" Apr 20 18:17:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:35 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:35 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 95. Apr 20 18:17:38 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:38 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:38 volumio go-librespot[4170]: Librespot-go daemon starting... Apr 20 18:17:38 volumio go-librespot[4170]: time="2024-04-20T18:17:38+08:00" level=info msg="generated new device id: b4282af8d013baec766cf0c9a48f055316ea2c5c" Apr 20 18:17:38 volumio go-librespot[4170]: time="2024-04-20T18:17:38+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:38 volumio go-librespot[4170]: time="2024-04-20T18:17:38+08:00" level=debug msg="obtained new client token: AAAOcv/9nU38Dmm8g+E0rMjv7FUnOa5zRWH/LZN4qnsAU4jmWgR5wDA43AhwwSsSD+M9r3kdVkH7PLeugsu+UV3JS8j0aOU7jnqzMAZGOfNKnIEQDMwctTZHSyuyNth/geNEUeWJL1hRrmwmWLBUVoUjB3pMIsp3ZY9h7uCw5y4nPU9C8uF04lNthLNlmkSj31Qr3zTvKYk8lI11dy3r+RnLlFUsS8NmAyu98t8B+YDyLhgpHKZ7Zi6hMMcASg==" Apr 20 18:17:38 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:38 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:17:38 volumio go-librespot[4170]: time="2024-04-20T18:17:38+08:00" level=debug msg="new websocket client" Apr 20 18:17:38 volumio go-librespot[4170]: time="2024-04-20T18:17:38+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:17:38 volumio go-librespot[4170]: time="2024-04-20T18:17:38+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:39 volumio go-librespot[4170]: time="2024-04-20T18:17:39+08:00" level=debug msg="completed challenge" Apr 20 18:17:39 volumio go-librespot[4170]: time="2024-04-20T18:17:39+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: TravelRestriction" Apr 20 18:17:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:39 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:17:41 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:17:41 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:41 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:17:41 volumio volumio[856]: (node:856) 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: 902) Apr 20 18:17:41 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14 Apr 20 18:17:41 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:17:41 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:41 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:42 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:42 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:42 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 96. Apr 20 18:17:42 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:42 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:42 volumio go-librespot[4190]: Librespot-go daemon starting... Apr 20 18:17:42 volumio go-librespot[4190]: time="2024-04-20T18:17:42+08:00" level=info msg="generated new device id: cded1e9b5bee99018a728deb7c2326bec2771380" Apr 20 18:17:42 volumio go-librespot[4190]: time="2024-04-20T18:17:42+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:43 volumio go-librespot[4190]: time="2024-04-20T18:17:43+08:00" level=debug msg="obtained new client token: AACZ2ftMVK8pNxM+SJ50ry5r8Ic+z9omoHr5+iM56SQf2Y2/BImyzB3Menl9/2jxErgvDSiIE96BAU7mYvBTHaBbkYe41wZrfeazwjOdpOExcrde9KF8cklRz6Pu5GV4qnfpSJx5DrGOi6JXDK9gpfh3h9klyOx1Omqdny32B9aq800N/x152oJn9rFnmfSzPMbCEiPhJqBtGJaTsq1+E+pCFnmJ9iOeBRsfheZvjAXpVZOMFAGUr08QPdE=" Apr 20 18:17:43 volumio go-librespot[4190]: time="2024-04-20T18:17: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:17:43 volumio go-librespot[4190]: time="2024-04-20T18:17:43+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:44 volumio go-librespot[4190]: time="2024-04-20T18:17:44+08:00" level=debug msg="completed challenge" Apr 20 18:17:44 volumio go-librespot[4190]: time="2024-04-20T18:17:44+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: TravelRestriction" Apr 20 18:17:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:45 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:45 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 97. Apr 20 18:17:47 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:47 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:47 volumio go-librespot[4208]: Librespot-go daemon starting... Apr 20 18:17:47 volumio go-librespot[4208]: time="2024-04-20T18:17:47+08:00" level=info msg="generated new device id: 58a34f34e4d33e680d84d1cdd82afe69813fbc78" Apr 20 18:17:47 volumio go-librespot[4208]: time="2024-04-20T18:17:47+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:48 volumio go-librespot[4208]: time="2024-04-20T18:17:48+08:00" level=debug msg="obtained new client token: AAD18eCJnUAsPa218Huc9Nf2LLF8w0z9XFcqwgumtVfzAbvMVj0Ji4C1ByWc/aYFaPCaTUzfyuh4akaUca2aInZAYFjFt5dRIm/maOQaKCPwOXrbm2eeq3/403YLsh4dBTSaVk1+wdnvIPW9v+vHrxu8wCHTJpiB9zy56i/CdUaJnsCLjXTqYdDRwl+5wUMpjYucmmSjjAANSY2srd8JgWdtV1HBts2wHZAfSbL68cDkumtnfLdhHOhZorY=" Apr 20 18:17:48 volumio go-librespot[4208]: time="2024-04-20T18:17:48+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:17:48 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:48 volumio go-librespot[4208]: time="2024-04-20T18:17:48+08:00" level=debug msg="new websocket client" Apr 20 18:17:48 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:17:49 volumio go-librespot[4208]: time="2024-04-20T18:17:49+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:49 volumio go-librespot[4208]: time="2024-04-20T18:17:49+08:00" level=debug msg="completed challenge" Apr 20 18:17:50 volumio go-librespot[4208]: time="2024-04-20T18:17:50+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: TravelRestriction" Apr 20 18:17:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:50 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:17:50 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 20 18:17:50 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 20 18:17:50 volumio volumio[856]: info: Discovery: Getting this device information Apr 20 18:17:50 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:17:50 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:50 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 20 18:17:51 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:17:51 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:51 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:17:51 volumio volumio[856]: (node:856) 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: 903) Apr 20 18:17:51 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 14 Apr 20 18:17:51 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:17:51 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:17:51 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:17:53 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:53 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:53 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Apr 20 18:17:53 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:53 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:53 volumio go-librespot[4226]: Librespot-go daemon starting... Apr 20 18:17:53 volumio go-librespot[4226]: time="2024-04-20T18:17:53+08:00" level=info msg="generated new device id: a5279ea1b050ca6df3ea886554c0373765ac50b5" Apr 20 18:17:53 volumio go-librespot[4226]: time="2024-04-20T18:17:53+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:53 volumio go-librespot[4226]: time="2024-04-20T18:17:53+08:00" level=debug msg="obtained new client token: AAAaLxs1e4/vmUMcAjjr49rZCCuwJxPitNgEkTBA9i4a2BXgKYlZvZQ2Tc1kXw77ZDNgg+Vc7IZpxpRWn0rimdKC9e6NeL0UnqMyUYJjC4yOnn/C0g1nD75ofXWfmS6jHB9a+U9lcDZrNs94G2fq2TdpXW7FdJewdgBajHztPzwvz9xTR2bXx6yV9bOyVipvicGNOGlqWq4vVkwC7CJcdC/DrDQXL6u6P+gKNpACVC4UvbPsfHJDJ41/tT8N6w==" Apr 20 18:17:54 volumio go-librespot[4226]: time="2024-04-20T18:17:54+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 20 18:17:54 volumio go-librespot[4226]: time="2024-04-20T18:17:54+08:00" level=debug msg="completed keyexchange" Apr 20 18:17:55 volumio go-librespot[4226]: time="2024-04-20T18:17:55+08:00" level=debug msg="completed challenge" Apr 20 18:17:55 volumio go-librespot[4226]: time="2024-04-20T18:17:55+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 20 18:17:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:17:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:17:56 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:56 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:17:58 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:17:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Apr 20 18:17:58 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:17:58 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:17:58 volumio go-librespot[4244]: Librespot-go daemon starting... Apr 20 18:17:58 volumio go-librespot[4244]: time="2024-04-20T18:17:58+08:00" level=info msg="generated new device id: b374cb769763218c042447db03e49e9ebdb80ac4" Apr 20 18:17:58 volumio go-librespot[4244]: time="2024-04-20T18:17:58+08:00" level=debug msg="stored credentials not found" Apr 20 18:17:59 volumio go-librespot[4244]: time="2024-04-20T18:17:59+08:00" level=debug msg="obtained new client token: AAAAXxfHxPw6GMwrnH8mwwTCpMRGh3n72zEpnKN2jPcjEY4xjTfRulWWPMI5rktNMqY2oQas38dCizoIxnx8MaY1EClWNrHI68UtCfoKjgvfCh6brtcPnMkyag6rabmzTwfPPUMyjyJuCQrk1MMuPXbVGm7mMztzQMuCZEHK+R6uwGtHY0UReGEnZ4xa1DKXnmVLZ4mMcGdqM3ajoOU75wBPVVmj7ANj+Uxk5MeuM7c/NODaLlsT/+kKncPClw==" Apr 20 18:17:59 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:17:59 volumio go-librespot[4244]: time="2024-04-20T18:17:59+08:00" level=debug msg="new websocket client" Apr 20 18:17:59 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:17:59 volumio go-librespot[4244]: time="2024-04-20T18:17:59+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 20 18:17:59 volumio go-librespot[4244]: time="2024-04-20T18:17:59+08:00" level=debug msg="completed keyexchange" Apr 20 18:18:00 volumio go-librespot[4244]: time="2024-04-20T18:18:00+08:00" level=debug msg="completed challenge" Apr 20 18:18:00 volumio go-librespot[4244]: time="2024-04-20T18:18: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: TravelRestriction" Apr 20 18:18:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:18:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:18:00 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:18:02 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:18:02 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:02 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:18:02 volumio volumio[856]: (node:856) 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: 904) Apr 20 18:18:02 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12 Apr 20 18:18:02 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:18:02 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:02 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:03 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:18:03 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:18:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Apr 20 18:18:03 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:18:03 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:18:03 volumio go-librespot[4263]: Librespot-go daemon starting... Apr 20 18:18:03 volumio go-librespot[4263]: time="2024-04-20T18:18:03+08:00" level=info msg="generated new device id: cc925bd8c9e190b0782cd1fa9da5fc7610e079e4" Apr 20 18:18:03 volumio go-librespot[4263]: time="2024-04-20T18:18:03+08:00" level=debug msg="stored credentials not found" Apr 20 18:18:04 volumio go-librespot[4263]: time="2024-04-20T18:18:04+08:00" level=debug msg="obtained new client token: AACa40opVz+Y5eosU3grlBsiHReY1C5+TbQA+k7w0vX0SHf5/4iD71SuGO/awQclkaZQ8dN1iHQ4pBdBjHGVKZLY9D4RkPRJGHkDwIiGYBs7MQnTMULoKSCDiZJ8UD81TYnSecso0ntv2zpwytNoBJZICWhiAA3Xyp41uK5MHECf8EKW45LX4byQu54MpvzFzRXZTzQ1GwUV6Y6he6abpzM3k5C6o6bWIFyCrP/xVSqMbmatWMkl8x/rPLQ=" Apr 20 18:18:04 volumio go-librespot[4263]: time="2024-04-20T18:18:04+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:18:05 volumio go-librespot[4263]: time="2024-04-20T18:18:05+08:00" level=debug msg="completed keyexchange" Apr 20 18:18:05 volumio go-librespot[4263]: time="2024-04-20T18:18:05+08:00" level=debug msg="completed challenge" Apr 20 18:18:05 volumio go-librespot[4263]: time="2024-04-20T18:18: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: TravelRestriction" Apr 20 18:18:05 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:18:05 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:18:06 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:18:06 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:18:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Apr 20 18:18:09 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:18:09 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:18:09 volumio go-librespot[4283]: Librespot-go daemon starting... Apr 20 18:18:09 volumio go-librespot[4283]: time="2024-04-20T18:18:09+08:00" level=info msg="generated new device id: d670cbf4f282d2e0d744b7cbd2c9a093249740b7" Apr 20 18:18:09 volumio go-librespot[4283]: time="2024-04-20T18:18:09+08:00" level=debug msg="stored credentials not found" Apr 20 18:18:09 volumio go-librespot[4283]: time="2024-04-20T18:18:09+08:00" level=debug msg="obtained new client token: AAA82mfsRnNSDxJ4Blukcamvh3LMetECtYxqUsWr45It8s2q1UQJe6JLt28HhpfOx1/qLG/+SZkPaUBWu4bWRLWsQOKURYzx/1xqxnSKPtnyax1t0uMcBJZKITHF2CgZ5kMd2U0qJQSifqYL2KiF0Cxn12jB5mVyp1Vk+On9zA2jGZIvSI07s1VfPsjt0pZSQvjvZGMF6VjIJvmANqMxQWJEjfCYRxwJTEaBCTD9kU8OuO8AwKOAjnWMxXXEXA==" Apr 20 18:18:09 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:18:09 volumio go-librespot[4283]: time="2024-04-20T18:18:09+08:00" level=debug msg="new websocket client" Apr 20 18:18:09 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:18:09 volumio go-librespot[4283]: time="2024-04-20T18:18:09+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:18:10 volumio go-librespot[4283]: time="2024-04-20T18:18:10+08:00" level=debug msg="completed keyexchange" Apr 20 18:18:10 volumio go-librespot[4283]: time="2024-04-20T18:18:10+08:00" level=debug msg="completed challenge" Apr 20 18:18:11 volumio go-librespot[4283]: time="2024-04-20T18:18:11+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: TravelRestriction" Apr 20 18:18:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:18:11 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:18:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:18:12 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:18:12 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:12 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:18:12 volumio volumio[856]: (node:856) 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: 905) Apr 20 18:18:12 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 20 18:18:12 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:18:12 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:12 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:14 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:18:14 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:18:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Apr 20 18:18:14 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:18:14 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:18:14 volumio go-librespot[4301]: Librespot-go daemon starting... Apr 20 18:18:14 volumio go-librespot[4301]: time="2024-04-20T18:18:14+08:00" level=info msg="generated new device id: eac03868ea90bc13ef1d4972dd5409bd6873406a" Apr 20 18:18:14 volumio go-librespot[4301]: time="2024-04-20T18:18:14+08:00" level=debug msg="stored credentials not found" Apr 20 18:18:14 volumio go-librespot[4301]: time="2024-04-20T18:18:14+08:00" level=debug msg="obtained new client token: AACPH12w42ECc/iIP12z2NKjUzt261FQWLCzz1KGxuO0WClOGfzcomFK4cilBUt+ebJHLe4b2Yxzw9SdBtfb3Tn89n8v10g/dMSlb7xekA3Xv55bfde4hbFv7+aDYkDtHCNOEGZcv3PPxP2v2a1TDqEAKiNZqdlzbRsxvb2+usJH7hhcP44w94HvIet2vY9ox8jE08LJ0E2HHCozfsSJW4B3EwhnUcsAikXVFecP/MqR9w1V0zsxgobgOWZc+w==" Apr 20 18:18:14 volumio go-librespot[4301]: time="2024-04-20T18:18:14+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:18:15 volumio kernel: usb 1-1.2: USB disconnect, device number 5 Apr 20 18:18:15 volumio go-librespot[4301]: time="2024-04-20T18:18:15+08:00" level=debug msg="completed keyexchange" Apr 20 18:18:15 volumio volumio[856]: info: Partition removed: {"syspath":"/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.2/1-1.2:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","ACTION":"remove","DEVLINKS":"/dev/disk/by-label/\\xce\\xde\\xcb\\xf0U\\xc5\\xcc /dev/disk/by-partuuid/0290848a-01 /dev/disk/by-uuid/BE65-05FD /dev/disk/by-id/usb-VendorCo_ProductCode_9508101076469663532-0:0-part1 /dev/disk/by-path/platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1.2:1.0-scsi-0:0:0:0-part1","DEVNAME":"/dev/sda1","DEVPATH":"/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.2/1-1.2:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","DEVTYPE":"partition","DISKSEQ":"28","ID_BUS":"usb","ID_FS_LABEL":"____U__","ID_FS_LABEL_ENC":"\\xce\\xde\\xcb\\xf0U\\xc5\\xcc","ID_FS_TYPE":"vfat","ID_FS_USAGE":"filesystem","ID_FS_UUID":"BE65-05FD","ID_FS_UUID_ENC":"BE65-05FD","ID_FS_VERSION":"FAT32","ID_INSTANCE":"0:0","ID_MODEL":"ProductCode","ID_MODEL_ENC":"ProductCode\\x20\\x20\\x20\\x20\\x20","ID_MODEL_ID":"5678","ID_PART_ENTRY_DISK":"8:0","ID_PART_ENTRY_FLAGS":"0x80","ID_PART_ENTRY_NUMBER":"1","ID_PART_ENTRY_OFFSET":"64","ID_PART_ENTRY_SCHEME":"dos","ID_PART_ENTRY_SIZE":"61439936","ID_PART_ENTRY_TYPE":"0xc","ID_PART_ENTRY_UUID":"0290848a-01","ID_PART_TABLE_TYPE":"dos","ID_PART_TABLE_UUID":"0290848a","ID_PATH":"platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1.2:1.0-scsi-0:0:0:0","ID_PATH_TAG":"platform-fd500000_pcie-pci-0000_01_00_0-usb-0_1_2_1_0-scsi-0_0_0_0","ID_REVISION":"2.00","ID_SERIAL":"VendorCo_ProductCode_9508101076469663532-0:0","ID_SERIAL_SHORT":"9508101076469663532","ID_TYPE":"disk","ID_USB_DRIVER":"usb-storage","ID_USB_INTERFACES":":080650:","ID_USB_INTERFACE_NUM":"00","ID_VENDOR":"VendorCo","ID_VENDOR_ENC":"VendorCo","ID_VENDOR_ID":"346d","MAJOR":"8","MINOR":"1","PARTN":"1","SEQNUM":"1858","SUBSYSTEM":"block","TAGS":":systemd:","USEC_INITIALIZED":"408074639"} Apr 20 18:18:15 volumio sudo[4316]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /dev/sda1 Apr 20 18:18:15 volumio sudo[4316]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 20 18:18:15 volumio sudo[4316]: pam_unix(sudo:session): session closed for user root Apr 20 18:18:15 volumio volumio[856]: umount: /media/____U__: target is busy. Apr 20 18:18:15 volumio volumio[856]: error: Failed to umount ____U__: Error: Command failed: /usr/bin/sudo /bin/umount -f "/dev/sda1" Apr 20 18:18:15 volumio volumio[856]: umount: /media/____U__: target is busy. Apr 20 18:18:15 volumio go-librespot[4301]: time="2024-04-20T18:18:15+08:00" level=debug msg="completed challenge" Apr 20 18:18:15 volumio go-librespot[4301]: time="2024-04-20T18:18:15+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 20 18:18:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:18:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:18:17 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:18:17 volumio volumio[856]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:18:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Apr 20 18:18:19 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:18:19 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:18:19 volumio go-librespot[4324]: Librespot-go daemon starting... Apr 20 18:18:19 volumio go-librespot[4324]: time="2024-04-20T18:18:19+08:00" level=info msg="generated new device id: 80c3171ff493661de89af7eda9bada76d091e432" Apr 20 18:18:19 volumio go-librespot[4324]: time="2024-04-20T18:18:19+08:00" level=debug msg="stored credentials not found" Apr 20 18:18:19 volumio go-librespot[4324]: time="2024-04-20T18:18:19+08:00" level=debug msg="obtained new client token: AAA/+3m4+Vvmg4X63Y0Y57bJtab5fSu48Vlf8dNJxyS9Q4VLyZezqO+DhaIo5VGJtelS4N46l4nPYej+a91qdT2tS/0kHKp/OmMv44I2IDEN/8mHA8j9F4WfLEBEgkMaxmXy2GFSmj3iDmwFhHiwFJZVwFBHML/dkII5K3Qyy0yd3QeVJq/n97TLzgoIWggXrDunPwVisubyrSUWNkq2hL2L4tEG4w+egYOK9q/oSiB2C0mJU4vVN/BBpxkaYw==" Apr 20 18:18:19 volumio go-librespot[4324]: time="2024-04-20T18:18:19+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 20 18:18:20 volumio go-librespot[4324]: time="2024-04-20T18:18:20+08:00" level=debug msg="completed keyexchange" Apr 20 18:18:20 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:18:20 volumio go-librespot[4324]: time="2024-04-20T18:18:20+08:00" level=debug msg="new websocket client" Apr 20 18:18:20 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:18:20 volumio volumio[856]: info: Scanning removed location : "USB/____U__" Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: update Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32768) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32769) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32770) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32771) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32772) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32773) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32774) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32775) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32776) failed Apr 20 18:18:20 volumio kernel: FAT-fs (sda1): Directory bread(block 32777) failed Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: update Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: update Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: MPD Database updated - AlbumList cache refreshed Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: database Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: update Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: MPD Database updated - AlbumList cache refreshed Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: database Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: update Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: MPD Database updated - AlbumList cache refreshed Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: database Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: Apr 20 18:18:20 volumio volumio[856]: ---------------------------- MPD announces state update: update Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 27 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 26 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 25 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 24 milliseconds Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: info: Command Router : Notfying DB Updatefalse Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::Close All Modals sent Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: info: Command Router : Notfying DB Updatefalse Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::Close All Modals sent Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio go-librespot[4324]: time="2024-04-20T18:18:20+08:00" level=debug msg="completed challenge" Apr 20 18:18:20 volumio volumio[856]: info: Command Router : Notfying DB Updatefalse Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::Close All Modals sent Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 193 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 196 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 198 milliseconds Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: info: Command Router : Notfying DB Updatefalse Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::Close All Modals sent Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio go-librespot[4324]: time="2024-04-20T18:18:20+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: TravelRestriction" Apr 20 18:18:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:18:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 272 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 271 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 272 milliseconds Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: info: Command Router : Notfying DB Updatefalse Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::Close All Modals sent Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 328 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 326 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand status took 327 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 246 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 211 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 169 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 93 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 92 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 18 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 19 milliseconds Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: info: Command Router : Notfying DB Updatefalse Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::Close All Modals sent Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 489ms Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 489ms Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 489ms Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 474ms Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 474ms Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 473ms Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 473ms Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 121 milliseconds Apr 20 18:18:20 volumio volumio[856]: info: sendMpdCommand playlistinfo took 122 milliseconds Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: verbose: STATE SERVICE {"status":"play","position":0,"seek":58114,"duration":239,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???˱???","artist":"??¶","album":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:20 volumio volumio[856]: verbose: CURRENT POSITION 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState stateService play Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus play Apr 20 18:18:20 volumio volumio[856]: info: Received an update from plugin. extracting info from payload Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:20 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:20 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 523ms Apr 20 18:18:20 volumio volumio[856]: info: ------------------------------ 524ms Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:20 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:21 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:21 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:18:23 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:18:23 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:23 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:18:23 volumio volumio[856]: (node:856) 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: 906) Apr 20 18:18:23 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 20 18:18:23 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:18:23 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:23 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:23 volumio volumio[856]: info: peppy_screensaver: Start PeppyMeter Apr 20 18:18:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:18:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Apr 20 18:18:23 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:18:23 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:18:23 volumio go-librespot[4379]: Librespot-go daemon starting... Apr 20 18:18:23 volumio go-librespot[4379]: time="2024-04-20T18:18:23+08:00" level=info msg="generated new device id: 081822844efb3e50665ad3ea7e7421da79c61e63" Apr 20 18:18:23 volumio go-librespot[4379]: time="2024-04-20T18:18:23+08:00" level=debug msg="stored credentials not found" Apr 20 18:18:24 volumio volumio[856]: info: Initializing connection to go-librespot Websocket Apr 20 18:18:24 volumio go-librespot[4379]: time="2024-04-20T18:18:24+08:00" level=debug msg="new websocket client" Apr 20 18:18:24 volumio volumio[856]: info: Connection to go-librespot Websocket established Apr 20 18:18:24 volumio go-librespot[4379]: time="2024-04-20T18:18:24+08:00" level=debug msg="obtained new client token: AABdOW7upaY0CYiacDj7w+xjT8lacMj+1YTJb/NypmpP+uQ3mN+0ze4rVk9rh4ogwckmnfBIbHJl8GyUgTVg5T9wkvfUW4dz0+q0rgcV9EVD3pvQjGbxYlx8655NeU7hPb/SQg1TLEELNes4WQ8/Ou8GbxRWO39qaTR+GZbVvbqG3bJhpLUklDctR1vxL4Vi9WlqKcWWPEoJcOh1fxXC0UduCeicYuGUxL1UCHUi3lFCdCasRmwZprpwzLo=" Apr 20 18:18:24 volumio go-librespot[4379]: time="2024-04-20T18:18:24+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 20 18:18:24 volumio go-librespot[4379]: time="2024-04-20T18:18:24+08:00" level=debug msg="completed keyexchange" Apr 20 18:18:25 volumio go-librespot[4379]: time="2024-04-20T18:18:25+08:00" level=debug msg="completed challenge" Apr 20 18:18:25 volumio go-librespot[4379]: time="2024-04-20T18:18:25+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 20 18:18:25 volumio volumio[856]: info: Connection to go-librespot Websocket closed Apr 20 18:18:25 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 20 18:18:25 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioNext Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::next Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::stPlaybackTimer Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::updateTrackBlock Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrackBlock Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::serviceStop Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 6 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::serviceStop Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::stop Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand stop Apr 20 18:18:25 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at snd_soc_component_update_bits on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand stop took 15 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::play index undefined Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::startPlaybackTimer Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::clearAddPlayTracks USB/____U__/1.孙露WAV无损206首/005.爱上不该爱的人.wav Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::updateTrackBlock Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrackBlock Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand status took 3 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand stop took 2 milliseconds Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand clear Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:18:25 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand playlistinfo took 36 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand clear took 36 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand status took 34 milliseconds Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand add "USB/____U__/1.孙露WAV无损206首/005.爱上不该爱的人.wav" Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: 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":"???˱???(DSD)","uri":"USB/____U__/1.孙露WAV无损206首/004.爱人别走.wav","trackType":"wav"} Apr 20 18:18:25 volumio volumio[856]: verbose: CURRENT POSITION 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: No code Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 20 18:18:25 volumio volumio[856]: verbose: CURRENT POSITION 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: No code Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 20 18:18:25 volumio volumio[856]: verbose: CURRENT POSITION 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: No code Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 82ms Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 79ms Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 78ms Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:18:25 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:18:25 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:18:25 volumio volumio[856]: error: updateQueue error: null Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:18:25 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 52ms Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand add "USB/____U__/1.孙露WAV无损206首/005.爱上不该爱的人.wav" took 50 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 6ms Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 4ms Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand play Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:18:25 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces system playlist update Apr 20 18:18:25 volumio volumio[856]: info: Ignoring MPD Status Update Apr 20 18:18:25 volumio kernel: fat__get_entry: 342 callbacks suppressed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32800) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32801) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32802) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32803) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32804) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32805) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32806) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32807) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32808) failed Apr 20 18:18:25 volumio kernel: FAT-fs (sda1): Directory bread(block 32809) failed Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 63ms Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand play took 62 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 60ms Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 58ms Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:25 volumio volumio[856]: info: Apr 20 18:18:25 volumio volumio[856]: ---------------------------- MPD announces state update: player Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::getState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand status Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand status took 8 milliseconds Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand status took 9 milliseconds Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand status took 10 milliseconds Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseState Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand clearerror took 15 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand clearerror took 12 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand clearerror took 9 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 20 18:18:25 volumio volumio[856]: info: sendMpdCommand playlistinfo took 5 milliseconds Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:25 volumio volumio[856]: verbose: ControllerMpd::parseTrackInfo Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: 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/____U__/1.孙露WAV无损206首/005.爱上不该爱的人.wav","trackType":"wav"} Apr 20 18:18:25 volumio volumio[856]: verbose: CURRENT POSITION 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: No code Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: 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/____U__/1.孙露WAV无损206首/005.爱上不该爱的人.wav","trackType":"wav"} Apr 20 18:18:25 volumio volumio[856]: verbose: CURRENT POSITION 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: No code Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: ControllerMpd::pushState Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::servicePushState Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: 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/____U__/1.孙露WAV无损206首/005.爱上不该爱的人.wav","trackType":"wav"} Apr 20 18:18:25 volumio volumio[856]: verbose: CURRENT POSITION 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState stateService stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::syncState currentStatus stop Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: No code Apr 20 18:18:25 volumio volumio[856]: info: CoreStateMachine::pushState Apr 20 18:18:25 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:25 volumio volumio[856]: info: CoreCommandRouter::volumioPushState Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 70ms Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 70ms Apr 20 18:18:25 volumio volumio[856]: info: ------------------------------ 69ms Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:25 volumio volumio[856]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 20 18:18:25 volumio volumio[856]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 20 18:18:27 volumio volumio[856]: info: Getting Spotify volume Apr 20 18:18:27 volumio volumio[856]: (node:856) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 20 18:18:27 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 20 18:18:27 volumio volumio[856]: (node:856) 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: 907) Apr 20 18:18:27 volumio volumio[856]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 20 18:18:27 volumio volumio[856]: info: CoreCommandRouter::volumioGetState Apr 20 18:18:27 volumio volumio[856]: info: CorePlayQueue::getTrack 7 Apr 20 18:18:27 volumio volumio[856]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Apr 20 18:18:27 volumio volumio[856]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 20 18:18:27 volumio volumio[856]: Error: connect ETIMEDOUT 104.244.46.63:80 Apr 20 18:18:27 volumio volumio[856]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Apr 20 18:18:27 volumio volumio[856]: errno: -110, Apr 20 18:18:27 volumio volumio[856]: code: 'ETIMEDOUT', Apr 20 18:18:27 volumio volumio[856]: syscall: 'connect', Apr 20 18:18:27 volumio volumio[856]: address: '104.244.46.63', Apr 20 18:18:27 volumio volumio[856]: port: 80 Apr 20 18:18:27 volumio volumio[856]: } Apr 20 18:18:27 volumio volumio[856]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 20 18:18:28 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 20 18:18:28 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 105. Apr 20 18:18:28 volumio systemd[1]: Stopped go-librespot Daemon. Apr 20 18:18:28 volumio sudo[4410]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-20 18:17 Apr 20 18:18:28 volumio sudo[4410]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 20 18:18:28 volumio systemd[1]: Started go-librespot Daemon. Apr 20 18:18:28 volumio go-librespot[4411]: Librespot-go daemon starting... Apr 20 18:18:28 volumio go-librespot[4411]: time="2024-04-20T18:18:28+08:00" level=info msg="generated new device id: f104f38ac8f69110f3dc576c8c2cd4e8ba04fce4" Apr 20 18:18:28 volumio go-librespot[4411]: time="2024-04-20T18:18:28+08:00" level=debug msg="stored credentials not found" 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"