-- Logs begin at Thu 2019-02-14 18:11:59 CST, end at Thu 2024-05-09 23:41:01 CST. -- May 09 23:40:00 volumio go-librespot[2939]: time="2024-05-09T23:40:00+08:00" level=debug msg="obtained new client token: AABsN3sjRE/d9poAUcuPlQPzyIRqqR7a6w1NkyaGNRYSxJ9kHTcvF/jdhDyY8m8D2PVBg0c54+FjkH2EBf/sJQ3lbhPuBWvt+5xGc4+wQ58d0eyy6dUlGjTxcOF94CekLX5irD5lq+DFTPpDn7l5J8kgcyNIuNaRN1b+JFdBgxpYsVTuZtt2lSIymwf6OuXtpOUjXNeobEajsP4XrNMeeG1LnZNtfsO1Pgtq/zSYinheK5FAvGJWugjEJNkkYQ==" May 09 23:40:02 volumio go-librespot[2939]: time="2024-05-09T23:40: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-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 09 23:40:02 volumio volumio[851]: info: Getting Spotify volume May 09 23:40:02 volumio volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 09 23:40:02 volumio volumio[851]: info: CoreCommandRouter::volumioGetState May 09 23:40:02 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:02 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:02 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:02 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:02 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:03 volumio go-librespot[2939]: time="2024-05-09T23:40:03+08:00" level=debug msg="completed keyexchange" May 09 23:40:03 volumio go-librespot[2939]: time="2024-05-09T23:40:03+08:00" level=debug msg="completed challenge" May 09 23:40:03 volumio go-librespot[2939]: time="2024-05-09T23:40: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: BadCredentials" May 09 23:40:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:03 volumio volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: socket hang up May 09 23:40:03 volumio volumio[851]: at connResetException (internal/errors.js:607:14) May 09 23:40:03 volumio volumio[851]: at Socket.socketOnEnd (_http_client.js:493:23) May 09 23:40:03 volumio volumio[851]: at Socket.emit (events.js:327:22) May 09 23:40:03 volumio volumio[851]: at endReadableNT (internal/streams/readable.js:1327:12) May 09 23:40:03 volumio volumio[851]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 09 23:40:03 volumio volumio[851]: (node:851) 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: 67) May 09 23:40:03 volumio volumio[851]: info: Connection to go-librespot Websocket closed May 09 23:40:06 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:06 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 86. May 09 23:40:06 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:06 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:06 volumio go-librespot[2951]: Librespot-go daemon starting... May 09 23:40:06 volumio go-librespot[2951]: time="2024-05-09T23:40:06+08:00" level=info msg="generated new device id: c93f888c286da2ede5521b1e3903ab80507f8167" May 09 23:40:06 volumio go-librespot[2951]: time="2024-05-09T23:40:06+08:00" level=debug msg="stored credentials not found" May 09 23:40:07 volumio go-librespot[2951]: time="2024-05-09T23:40:07+08:00" level=debug msg="obtained new client token: AACiMX279DfGRkZkDSmInF5GM4MqQ3KgszCCWScDmCmL5V2QogO5ZVbpg35cdYlMhoz/FU5fhYNAMdxSczXwML9xQ97+SFWL129bM9hUVRrP36aJU7jc5Sj2t42zQJ5kA7MNd5DERDNryhwDiFFlbh0FMJwq2JV2v8iUZ4tNbEU3sCobzf5LSbB/uv8K+uwfqq+bdO9zrFKILk7NE4nhVgNRm2pNMSd7SCdf8Z7T1ofPOLTitMCG0LM2Pv6+RqWn" May 09 23:40:09 volumio go-librespot[2951]: time="2024-05-09T23:40: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" May 09 23:40:09 volumio go-librespot[2951]: time="2024-05-09T23:40:09+08:00" level=debug msg="completed keyexchange" May 09 23:40:09 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:09 volumio go-librespot[2951]: time="2024-05-09T23:40:09+08:00" level=debug msg="new websocket client" May 09 23:40:09 volumio volumio[851]: info: Connection to go-librespot Websocket established May 09 23:40:09 volumio go-librespot[2951]: time="2024-05-09T23:40:09+08:00" level=debug msg="completed challenge" May 09 23:40:09 volumio volumio[851]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] May 09 23:40:09 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions May 09 23:40:09 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 09 23:40:09 volumio go-librespot[2951]: time="2024-05-09T23:40: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: BadCredentials" May 09 23:40:09 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:09 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 09 23:40:10 volumio volumio[851]: info: Setting default mixerSoftMaster for Softvolume device May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 09 23:40:10 volumio volumio[851]: info: Updating Volume Controller Parameters: Device: 5 Name: softvolume Mixer: SoftMaster Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 09 23:40:10 volumio volumio[851]: info: Disabling external Volume Control May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::getUIConfigOnPlugin May 09 23:40:10 volumio volumio[851]: info: Enable softmixer device for audio device undefined May 09 23:40:10 volumio volumio[851]: info: Connection to go-librespot Websocket closed May 09 23:40:10 volumio volumio[851]: info: Software Volume ALSA configuration written May 09 23:40:10 volumio volumio[851]: info: Preparing to generate the ALSA configuration file May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 09 23:40:10 volumio volumio[851]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf May 09 23:40:10 volumio volumio[851]: info: The plugin peppy_screensaver has an ALSA contribution file Peppyalsa.postPeppyalsa.5.conf May 09 23:40:10 volumio volumio[851]: info: Reading ALSA contributions from plugins. May 09 23:40:10 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:10 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:10 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:10 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:10 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:10 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:10 volumio volumio[851]: info: Asound.conf file unchanged, so no further update is needed May 09 23:40:10 volumio volumio[851]: info: Output device has changed, restarting MPD May 09 23:40:10 volumio sudo[2979]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 09 23:40:10 volumio sudo[2979]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 23:40:10 volumio sudo[2979]: pam_unix(sudo:session): session closed for user root May 09 23:40:10 volumio volumio[851]: info: MPD Permissions set May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio sudo[2982]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 09 23:40:10 volumio sudo[2982]: pam_unix(sudo:session): session opened for user root by (uid=0) May 09 23:40:10 volumio systemd[1]: Stopping Music Player Daemon... May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio systemd[1]: mpd.service: Succeeded. May 09 23:40:10 volumio systemd[1]: Stopped Music Player Daemon. May 09 23:40:10 volumio systemd[1]: Starting Music Player Daemon... May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:10 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 09 23:40:11 volumio mpd[2988]: May 09 23:40 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 09 23:40:11 volumio systemd[1]: Started Music Player Daemon. May 09 23:40:11 volumio sudo[2982]: pam_unix(sudo:session): session closed for user root May 09 23:40:11 volumio volumio[851]: error: updateQueue error: null May 09 23:40:12 volumio volumio[851]: info: Getting Spotify volume May 09 23:40:12 volumio volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:12 volumio volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 09 23:40:12 volumio volumio[851]: (node:851) 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: 68) May 09 23:40:12 volumio volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 09 23:40:12 volumio volumio[851]: info: CoreCommandRouter::volumioGetState May 09 23:40:12 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:12 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:12 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:12 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:12 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:13 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:13 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 87. May 09 23:40:13 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:13 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:13 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:13 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:13 volumio go-librespot[2991]: Librespot-go daemon starting... May 09 23:40:13 volumio go-librespot[2991]: time="2024-05-09T23:40:13+08:00" level=info msg="generated new device id: 83eaf010a3a456276827ec63697ff304d044193b" May 09 23:40:13 volumio go-librespot[2991]: time="2024-05-09T23:40:13+08:00" level=debug msg="stored credentials not found" May 09 23:40:14 volumio volumio[851]: info: CoreCommandRouter::volumioRetrieveVolumeLevels May 09 23:40:14 volumio volumio[851]: info: CoreStateMachine::getcurrentVolume May 09 23:40:14 volumio volumio[851]: info: CoreCommandRouter::volumioRetrievevolume May 09 23:40:14 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:14 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:14 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 09 23:40:14 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:14 volumio volumio[851]: info: CoreStateMachine::updateTrackBlock May 09 23:40:14 volumio volumio[851]: info: CorePlayQueue::getTrackBlock May 09 23:40:14 volumio volumio[851]: info: CoreCommandRouter::volumioRetrievevolume May 09 23:40:14 volumio go-librespot[2991]: time="2024-05-09T23:40:14+08:00" level=debug msg="obtained new client token: AADNNt00EUE6NIddk50bLA8OzWZPWMxoN3jm410LesUQLlXlqxcvq4DKP90a3MCEYrF2qux+5M2QPlaNLPSijQWOTv/NXCcaNp1oX0ED4R3KUrSico5xvK+Da7MWJHy03lgyHzZNrSCU6F3QyLHP+ftRgEPT9tBD9wrmp1ds1ED4qljtEgSLsCaS1jXbA1zJPtN6PN/mp/bMDzJAUOzQ6zKQ6wweZ7Iyw5OIFNKZrFq2NEgI3zo5Qv/OAWQcKxA5" May 09 23:40:14 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:14 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:14 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:14 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:14 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:14 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:14 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 09 23:40:14 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:14 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:14 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:14 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:14 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:14 volumio go-librespot[2991]: time="2024-05-09T23:40: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-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 09 23:40:15 volumio go-librespot[2991]: time="2024-05-09T23:40:15+08:00" level=debug msg="completed keyexchange" May 09 23:40:15 volumio go-librespot[2991]: time="2024-05-09T23:40:15+08:00" level=debug msg="completed challenge" May 09 23:40:15 volumio go-librespot[2991]: time="2024-05-09T23:40:15+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 09 23:40:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:16 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:16 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88. May 09 23:40:18 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:18 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:18 volumio go-librespot[3047]: Librespot-go daemon starting... May 09 23:40:18 volumio go-librespot[3047]: time="2024-05-09T23:40:18+08:00" level=info msg="generated new device id: b3dbd568351d73c22018a4891086349899412634" May 09 23:40:18 volumio go-librespot[3047]: time="2024-05-09T23:40:18+08:00" level=debug msg="stored credentials not found" May 09 23:40:19 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:19 volumio go-librespot[3047]: time="2024-05-09T23:40:19+08:00" level=debug msg="new websocket client" May 09 23:40:19 volumio volumio[851]: info: Connection to go-librespot Websocket established May 09 23:40:20 volumio go-librespot[3047]: time="2024-05-09T23:40:20+08:00" level=debug msg="obtained new client token: AAANRUGPd3edA0zm5Ag0Dk+pFnBC4Fis0kBjocu4/0qY9bc7BpoNUu4XDImWuZnGPplUfOWDS/FEayKFp6POXrN+SvQUdDtatpk7dM4h6BzBc2GlwU7AeD4fIm9dwoPNUccKayxMno4LbjnYKS06nSO3ryjCKRRmDTVjHhqf5n5attr2NcXv1FQbEqTxKvpeaNfMCMi56aWq/woXwPPnh4V+niIcqPrLtWawF0xtVahvXf+DmbvAWt4VaZm8RYwk" May 09 23:40:20 volumio go-librespot[3047]: time="2024-05-09T23:40:20+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]" May 09 23:40:20 volumio go-librespot[3047]: time="2024-05-09T23:40:20+08:00" level=debug msg="completed keyexchange" May 09 23:40:21 volumio go-librespot[3047]: time="2024-05-09T23:40:21+08:00" level=debug msg="completed challenge" May 09 23:40:21 volumio go-librespot[3047]: time="2024-05-09T23:40:21+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 09 23:40:21 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:21 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:21 volumio volumio[851]: info: Connection to go-librespot Websocket closed May 09 23:40:22 volumio volumio[851]: info: Getting Spotify volume May 09 23:40:22 volumio volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:22 volumio volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 09 23:40:22 volumio volumio[851]: (node:851) 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: 69) May 09 23:40:22 volumio volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 09 23:40:22 volumio volumio[851]: info: CoreCommandRouter::volumioGetState May 09 23:40:22 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:22 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:22 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:22 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:22 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:22 volumio volumio[851]: info: CoreCommandRouter::volumioPlay May 09 23:40:22 volumio volumio[851]: info: CoreStateMachine::play index undefined May 09 23:40:22 volumio volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined May 09 23:40:22 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:22 volumio volumio[851]: info: CoreStateMachine::startPlaybackTimer May 09 23:40:22 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:22 volumio volumio[851]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3 May 09 23:40:22 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand stop May 09 23:40:22 volumio volumio[851]: info: sendMpdCommand stop took 1 milliseconds May 09 23:40:22 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand clear May 09 23:40:22 volumio volumio[851]: info: May 09 23:40:22 volumio volumio[851]: ---------------------------- MPD announces system playlist update May 09 23:40:22 volumio volumio[851]: info: Ignoring MPD Status Update May 09 23:40:22 volumio volumio[851]: info: sendMpdCommand clear took 1 milliseconds May 09 23:40:22 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3" May 09 23:40:22 volumio volumio[851]: error: updateQueue error: null May 09 23:40:22 volumio volumio[851]: info: May 09 23:40:22 volumio volumio[851]: ---------------------------- MPD announces system playlist update May 09 23:40:22 volumio volumio[851]: info: Ignoring MPD Status Update May 09 23:40:22 volumio volumio[851]: info: ------------------------------ 2ms May 09 23:40:22 volumio volumio[851]: info: sendMpdCommand add "USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3" took 2 milliseconds May 09 23:40:22 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand play May 09 23:40:22 volumio volumio[851]: info: ------------------------------ 2ms May 09 23:40:22 volumio volumio[851]: info: sendMpdCommand play took 2 milliseconds May 09 23:40:22 volumio volumio[851]: info: May 09 23:40:22 volumio volumio[851]: ---------------------------- MPD announces state update: player May 09 23:40:22 volumio volumio[851]: info: ControllerMpd::getState May 09 23:40:22 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand status May 09 23:40:23 volumio volumio[851]: info: CoreCommandRouter::volumioPlay May 09 23:40:23 volumio volumio[851]: info: CoreStateMachine::play index undefined May 09 23:40:23 volumio volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined May 09 23:40:23 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:23 volumio volumio[851]: info: CoreStateMachine::startPlaybackTimer May 09 23:40:23 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::clearAddPlayTracks USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3 May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand stop May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand status took 681 milliseconds May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::parseState May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 09 23:40:23 volumio volumio[851]: info: May 09 23:40:23 volumio volumio[851]: ---------------------------- MPD announces state update: player May 09 23:40:23 volumio volumio[851]: info: May 09 23:40:23 volumio volumio[851]: ---------------------------- MPD announces state update: player May 09 23:40:23 volumio volumio[851]: info: ControllerMpd::getState May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand status May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand stop took 180 milliseconds May 09 23:40:23 volumio volumio[851]: info: ControllerMpd::getState May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand status May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand playlistinfo took 80 milliseconds May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand clear May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::parseTrackInfo May 09 23:40:23 volumio volumio[851]: info: ControllerMpd::pushState May 09 23:40:23 volumio volumio[851]: info: CoreCommandRouter::servicePushState May 09 23:40:23 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:23 volumio volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":203,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"你怎么说","artist":"邓丽君","album":"BTB 邓丽君-在水一方","uri":"USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3","trackType":"mp3"} May 09 23:40:23 volumio volumio[851]: verbose: CURRENT POSITION 0 May 09 23:40:23 volumio volumio[851]: info: CoreStateMachine::syncState stateService play May 09 23:40:23 volumio volumio[851]: info: CoreStateMachine::syncState currentStatus stop May 09 23:40:23 volumio volumio[851]: info: ------------------------------ 764ms May 09 23:40:23 volumio volumio[851]: info: May 09 23:40:23 volumio volumio[851]: ---------------------------- MPD announces system playlist update May 09 23:40:23 volumio volumio[851]: info: Ignoring MPD Status Update May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand status took 19 milliseconds May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand clear took 18 milliseconds May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::parseState May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::parseState May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand add "USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3" May 09 23:40:23 volumio volumio[851]: error: updateQueue error: null May 09 23:40:23 volumio volumio[851]: info: May 09 23:40:23 volumio volumio[851]: ---------------------------- MPD announces system playlist update May 09 23:40:23 volumio volumio[851]: info: Ignoring MPD Status Update May 09 23:40:23 volumio volumio[851]: info: ------------------------------ 19ms May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand playlistinfo took 5 milliseconds May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand playlistinfo took 4 milliseconds May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand add "USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3" took 4 milliseconds May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::parseTrackInfo May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::parseTrackInfo May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand play May 09 23:40:23 volumio volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined May 09 23:40:23 volumio volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined May 09 23:40:23 volumio volumio[851]: info: ------------------------------ 28ms May 09 23:40:23 volumio volumio[851]: info: ------------------------------ 29ms May 09 23:40:23 volumio volumio[851]: info: ------------------------------ 6ms May 09 23:40:23 volumio volumio[851]: info: sendMpdCommand play took 3 milliseconds May 09 23:40:23 volumio volumio[851]: info: May 09 23:40:23 volumio volumio[851]: ---------------------------- MPD announces state update: player May 09 23:40:23 volumio volumio[851]: info: ControllerMpd::getState May 09 23:40:23 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand status May 09 23:40:24 volumio volumio[851]: info: May 09 23:40:24 volumio volumio[851]: ---------------------------- MPD announces state update: player May 09 23:40:24 volumio volumio[851]: info: sendMpdCommand status took 580 milliseconds May 09 23:40:24 volumio volumio[851]: info: ControllerMpd::getState May 09 23:40:24 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand status May 09 23:40:24 volumio volumio[851]: verbose: ControllerMpd::parseState May 09 23:40:24 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 09 23:40:24 volumio volumio[851]: info: sendMpdCommand status took 1 milliseconds May 09 23:40:24 volumio volumio[851]: verbose: ControllerMpd::parseState May 09 23:40:24 volumio volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 09 23:40:24 volumio volumio[851]: info: sendMpdCommand playlistinfo took 2 milliseconds May 09 23:40:24 volumio volumio[851]: info: sendMpdCommand playlistinfo took 0 milliseconds May 09 23:40:24 volumio volumio[851]: verbose: ControllerMpd::parseTrackInfo May 09 23:40:24 volumio volumio[851]: verbose: ControllerMpd::parseTrackInfo May 09 23:40:24 volumio volumio[851]: info: ControllerMpd::pushState May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::servicePushState May 09 23:40:24 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:24 volumio volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":203,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"你怎么说","artist":"邓丽君","album":"BTB 邓丽君-在水一方","uri":"USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3","trackType":"mp3"} May 09 23:40:24 volumio volumio[851]: verbose: CURRENT POSITION 0 May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::syncState stateService play May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::syncState currentStatus play May 09 23:40:24 volumio volumio[851]: info: Received an update from plugin. extracting info from payload May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:24 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:24 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:24 volumio volumio[851]: info: ControllerMpd::pushState May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::servicePushState May 09 23:40:24 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:24 volumio volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":628,"duration":203,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"你怎么说","artist":"邓丽君","album":"BTB 邓丽君-在水一方","uri":"USB/288016118015E65A/kgmusic/邓丽君 - 你怎么说.mp3","trackType":"mp3"} May 09 23:40:24 volumio volumio[851]: verbose: CURRENT POSITION 0 May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::syncState stateService play May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::syncState currentStatus play May 09 23:40:24 volumio volumio[851]: info: Received an update from plugin. extracting info from payload May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:24 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:24 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:24 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:24 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:24 volumio volumio[851]: info: ------------------------------ 631ms May 09 23:40:24 volumio volumio[851]: info: ------------------------------ 52ms May 09 23:40:24 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:24 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:24 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:24 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:24 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:24 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:24 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:24 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:24 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 89. May 09 23:40:24 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:24 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:24 volumio go-librespot[3060]: Librespot-go daemon starting... May 09 23:40:24 volumio go-librespot[3060]: time="2024-05-09T23:40:24+08:00" level=info msg="generated new device id: 8a30208f477dd05bea10c65eb67670e86ba8e7be" May 09 23:40:24 volumio go-librespot[3060]: time="2024-05-09T23:40:24+08:00" level=debug msg="stored credentials not found" May 09 23:40:25 volumio go-librespot[3060]: time="2024-05-09T23:40:25+08:00" level=debug msg="obtained new client token: AABrL9tYFVA+W5hkx4qr08n8SYGkLWnrJQNqwSH39MXGcfIXWFdLHS8vd5yKGzzJqMETDn0uwmT8HzUl938CztYoCzJXxz/5QuFQZvUtYkkiSWRzYsZKp36quvkTb2GjYopJ1qQYK7bZloa9QPUNEdLCp7hB52Vt5yVxYBYWTTUOl/kPUgDeIw9A0+cXCy1VDVc1AElCTk4cQ1YCiCfM5zBhaRllRhnIK5Yt3N21Fm6IwPEtMzg3CO9jZFyLks1A" May 09 23:40:25 volumio go-librespot[3060]: time="2024-05-09T23:40:25+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]" May 09 23:40:26 volumio go-librespot[3060]: time="2024-05-09T23:40:26+08:00" level=debug msg="completed keyexchange" May 09 23:40:26 volumio go-librespot[3060]: time="2024-05-09T23:40:26+08:00" level=debug msg="completed challenge" May 09 23:40:26 volumio go-librespot[3060]: time="2024-05-09T23:40:26+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 09 23:40:26 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:26 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:27 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:27 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:29 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:29 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 90. May 09 23:40:29 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:29 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:29 volumio go-librespot[3068]: Librespot-go daemon starting... May 09 23:40:29 volumio go-librespot[3068]: time="2024-05-09T23:40:29+08:00" level=info msg="generated new device id: a0669ae285d49a1c72ba2dc9893b4746c86fa321" May 09 23:40:29 volumio go-librespot[3068]: time="2024-05-09T23:40:29+08:00" level=debug msg="stored credentials not found" May 09 23:40:30 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:30 volumio go-librespot[3068]: time="2024-05-09T23:40:30+08:00" level=debug msg="new websocket client" May 09 23:40:30 volumio volumio[851]: info: Connection to go-librespot Websocket established May 09 23:40:30 volumio go-librespot[3068]: time="2024-05-09T23:40:30+08:00" level=debug msg="obtained new client token: AAAfiLtlUl/BcOX7uRo+sJ3kF82cnu/6MbO7m5Ig5vdZviVngZWtiY0sh3+V+yUUEYNmhsW3rLgDsvXFdRXQNgkObcRtH7pV9ac6P2f1pYVotXqVjyy2/IfSmqaXukBqRwJ2b7SItu9HiR9gG756TXbEaQBq/8gr9PAyiCMVn95eL+iVC1rlwmayV6eUCI8maybBQRtWZMvw7K5EisuUhLsgckQzh/jtfh7pBJAoGDcbQKneh7RLsxwCXbwoVixN" May 09 23:40:32 volumio go-librespot[3068]: time="2024-05-09T23:40:32+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]" May 09 23:40:32 volumio go-librespot[3068]: time="2024-05-09T23:40:32+08:00" level=debug msg="completed keyexchange" May 09 23:40:33 volumio go-librespot[3068]: time="2024-05-09T23:40:33+08:00" level=debug msg="completed challenge" May 09 23:40:33 volumio go-librespot[3068]: time="2024-05-09T23:40:33+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 09 23:40:33 volumio volumio[851]: info: Connection to go-librespot Websocket closed May 09 23:40:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:33 volumio volumio[851]: info: Getting Spotify volume May 09 23:40:33 volumio volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:33 volumio volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 09 23:40:33 volumio volumio[851]: (node:851) 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: 70) May 09 23:40:33 volumio volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 09 23:40:33 volumio volumio[851]: info: CoreCommandRouter::volumioGetState May 09 23:40:33 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:33 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:33 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:33 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:33 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:35 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri May 09 23:40:35 volumio volumio[851]: info: CURURI: playlists May 09 23:40:35 volumio volumio[851]: info: Listing playlists May 09 23:40:35 volumio volumio[851]: info: Preload queue cleared May 09 23:40:36 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:36 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 91. May 09 23:40:36 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:36 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:36 volumio go-librespot[3076]: Librespot-go daemon starting... May 09 23:40:36 volumio go-librespot[3076]: time="2024-05-09T23:40:36+08:00" level=info msg="generated new device id: e86ab61245a434cf48dd31f31bdb1e33c3509511" May 09 23:40:36 volumio go-librespot[3076]: time="2024-05-09T23:40:36+08:00" level=debug msg="stored credentials not found" May 09 23:40:37 volumio volumio[851]: info: Preload queue cleared May 09 23:40:37 volumio volumio[851]: info: Preloading song: spotify:track:45bMR5YEj1fsOVkcHbVW6s May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track01.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track02.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track03.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track04.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track05.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track06.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track07.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track08.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track09.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track10.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track11.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track12.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track13.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track14.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track15.mp3 May 09 23:40:37 volumio volumio[851]: info: Preloading song: mnt/USB/288016118015E65A/muse/蔡琴.-.[试音.蔡琴].专辑.(APE).ape May 09 23:40:37 volumio volumio[851]: info: Exploding uri spotify:track:45bMR5YEj1fsOVkcHbVW6s in service spop May 09 23:40:37 volumio volumio[851]: SPOTIFY: EXPLODING URI:spotify:track:45bMR5YEj1fsOVkcHbVW6s May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track01.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track01.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track02.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track02.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track03.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track03.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track04.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track04.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track05.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track05.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track06.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track06.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track07.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track07.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track08.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track08.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track09.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track09.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track10.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track10.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track11.mp3 in service mpd May 09 23:40:37 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track11.mp3' May 09 23:40:37 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track12.mp3 in service mpd May 09 23:40:38 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track12.mp3' May 09 23:40:38 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track13.mp3 in service mpd May 09 23:40:38 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track13.mp3' May 09 23:40:38 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track14.mp3 in service mpd May 09 23:40:38 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track14.mp3' May 09 23:40:38 volumio volumio[851]: info: Exploding uri music-library/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track15.mp3 in service mpd May 09 23:40:38 volumio volumio[851]: error: scanFolder - failure to stat '/mnt/USB/music/捌零青青 - 非听勿扰Ⅱ·极致男声 DSD/未知艺术家 - Track15.mp3' May 09 23:40:38 volumio volumio[851]: info: Exploding uri mnt/USB/288016118015E65A/muse/蔡琴.-.[试音.蔡琴].专辑.(APE).ape in service mpd May 09 23:40:38 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2Fmuse%2F%E8%94%A1%E7%90%B4.-.%5B%E8%AF%95%E9%9F%B3.%E8%94%A1%E7%90%B4%5D.%E4%B8%93%E8%BE%91.(APE).ape&metadata=false May 09 23:40:38 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/muse/蔡琴.-.[试音.蔡琴].专辑.(APE).ape May 09 23:40:38 volumio go-librespot[3076]: time="2024-05-09T23:40:38+08:00" level=debug msg="obtained new client token: AAAG+w17YBYet0BN+JUCwLiaH9LhoqEcJuh43nhZTHEDn7+Q9S26o/8B+nt7m4I6dYAFTNlJQNRfAdMB4EM6mLkolg6QXKsSSSHUyeYboyG7TgZ+Ll4Xia+AFAAX+HIAx1yN3CKpUBZUDHw7e4FBj28CK1YwiLYIq/4q2bIsNZUXbfQgVxvYy0SpaqBAAncdGfUriUzq9M4GRBEXexvx0wN5ZuZ5m55mHyDTV0NlFZlUoeB3YdZ5O6hNSWhLHIvL" May 09 23:40:39 volumio volumio[851]: error: Commandrouter: Cannot explode uri spotify:track:45bMR5YEj1fsOVkcHbVW6s from service spop: Error: Spotify API method getTrack failed: WebapiRegularError: An error occurred while communicating with Spotify's Web API. May 09 23:40:39 volumio volumio[851]: Details: No token provided. May 09 23:40:39 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:39 volumio go-librespot[3076]: time="2024-05-09T23:40:39+08:00" level=debug msg="new websocket client" May 09 23:40:39 volumio volumio[851]: info: Connection to go-librespot Websocket established May 09 23:40:39 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri May 09 23:40:39 volumio volumio[851]: info: CURURI: music-library May 09 23:40:39 volumio go-librespot[3076]: time="2024-05-09T23:40:39+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" May 09 23:40:39 volumio volumio[851]: info: Preload queue cleared May 09 23:40:39 volumio go-librespot[3076]: time="2024-05-09T23:40:39+08:00" level=debug msg="completed keyexchange" May 09 23:40:40 volumio go-librespot[3076]: time="2024-05-09T23:40:40+08:00" level=debug msg="completed challenge" May 09 23:40:40 volumio go-librespot[3076]: time="2024-05-09T23:40:40+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 09 23:40:40 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:40 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:40 volumio volumio[851]: info: Connection to go-librespot Websocket closed May 09 23:40:40 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri May 09 23:40:40 volumio volumio[851]: info: CURURI: music-library/USB May 09 23:40:40 volumio volumio[851]: info: Preload queue cleared May 09 23:40:42 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri May 09 23:40:42 volumio volumio[851]: info: CURURI: music-library/USB/288016118015E65A May 09 23:40:42 volumio volumio[851]: info: Preload queue cleared May 09 23:40:42 volumio volumio[851]: info: Preloading song: music-library/USB/288016118015E65A/【dy2090.com】九鼎记之禹皇宝藏.2023.1080P.国语中字无水印.mp4 May 09 23:40:42 volumio volumio[851]: info: Preloading song: music-library/USB/288016118015E65A/200812_东成西就(粤语).rmvb May 09 23:40:42 volumio volumio[851]: info: Preloading song: music-library/USB/288016118015E65A/变形金刚：超能勇士崛起-2023_HD中英双字.mp4 May 09 23:40:42 volumio volumio[851]: info: Preloading song: music-library/USB/288016118015E65A/唬胆特工-2022_BD中英双字.mp4 May 09 23:40:42 volumio volumio[851]: info: Preloading song: music-library/USB/288016118015E65A/敢死队4：最终章.2023.HD1080P.AAC.H264.CHS-ENG.mp4 May 09 23:40:42 volumio volumio[851]: info: Preloading song: music-library/USB/288016118015E65A/速度与激情10-2023_HD中英双字V1.mp4 May 09 23:40:42 volumio volumio[851]: info: Preloading song: music-library/USB/288016118015E65A/阿凡达：水之道-2022_HDTC中英双字V2.mp4 May 09 23:40:42 volumio volumio[851]: info: Exploding uri music-library/USB/288016118015E65A/【dy2090.com】九鼎记之禹皇宝藏.2023.1080P.国语中字无水印.mp4 in service mpd May 09 23:40:42 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2F%E3%80%90dy2090.com%E3%80%91%E4%B9%9D%E9%BC%8E%E8%AE%B0%E4%B9%8B%E7%A6%B9%E7%9A%87%E5%AE%9D%E8%97%8F.2023.1080P.%E5%9B%BD%E8%AF%AD%E4%B8%AD%E5%AD%97%E6%97%A0%E6%B0%B4%E5%8D%B0.mp4&metadata=false May 09 23:40:42 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/【dy2090.com】九鼎记之禹皇宝藏.2023.1080P.国语中字无水印.mp4 May 09 23:40:42 volumio volumio[851]: info: Exploding uri music-library/USB/288016118015E65A/200812_东成西就(粤语).rmvb in service mpd May 09 23:40:42 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2F200812_%E4%B8%9C%E6%88%90%E8%A5%BF%E5%B0%B1(%E7%B2%A4%E8%AF%AD).rmvb&metadata=false May 09 23:40:42 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/200812_东成西就(粤语).rmvb May 09 23:40:42 volumio volumio[851]: info: Getting Spotify volume May 09 23:40:42 volumio volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:42 volumio volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) May 09 23:40:42 volumio volumio[851]: (node:851) 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: 71) May 09 23:40:42 volumio volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 May 09 23:40:42 volumio volumio[851]: info: CoreCommandRouter::volumioGetState May 09 23:40:42 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:42 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:42 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:42 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:42 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:42 volumio volumio[851]: info: Exploding uri music-library/USB/288016118015E65A/变形金刚：超能勇士崛起-2023_HD中英双字.mp4 in service mpd May 09 23:40:42 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2F%E5%8F%98%E5%BD%A2%E9%87%91%E5%88%9A%EF%BC%9A%E8%B6%85%E8%83%BD%E5%8B%87%E5%A3%AB%E5%B4%9B%E8%B5%B7-2023_HD%E4%B8%AD%E8%8B%B1%E5%8F%8C%E5%AD%97.mp4&metadata=false May 09 23:40:42 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/变形金刚：超能勇士崛起-2023_HD中英双字.mp4 May 09 23:40:42 volumio volumio[851]: info: Exploding uri music-library/USB/288016118015E65A/唬胆特工-2022_BD中英双字.mp4 in service mpd May 09 23:40:42 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2F%E5%94%AC%E8%83%86%E7%89%B9%E5%B7%A5-2022_BD%E4%B8%AD%E8%8B%B1%E5%8F%8C%E5%AD%97.mp4&metadata=false May 09 23:40:42 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/唬胆特工-2022_BD中英双字.mp4 May 09 23:40:42 volumio volumio[851]: info: Exploding uri music-library/USB/288016118015E65A/敢死队4：最终章.2023.HD1080P.AAC.H264.CHS-ENG.mp4 in service mpd May 09 23:40:42 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2F%E6%95%A2%E6%AD%BB%E9%98%9F4%EF%BC%9A%E6%9C%80%E7%BB%88%E7%AB%A0.2023.HD1080P.AAC.H264.CHS-ENG.mp4&metadata=false May 09 23:40:42 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/敢死队4：最终章.2023.HD1080P.AAC.H264.CHS-ENG.mp4 May 09 23:40:42 volumio volumio[851]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 May 09 23:40:42 volumio volumio[851]: info: Exploding uri music-library/USB/288016118015E65A/速度与激情10-2023_HD中英双字V1.mp4 in service mpd May 09 23:40:42 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2F%E9%80%9F%E5%BA%A6%E4%B8%8E%E6%BF%80%E6%83%8510-2023_HD%E4%B8%AD%E8%8B%B1%E5%8F%8C%E5%AD%97V1.mp4&metadata=false May 09 23:40:42 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/速度与激情10-2023_HD中英双字V1.mp4 May 09 23:40:42 volumio volumio[851]: info: touch_display: Setting screensaver timeout to 15 seconds. May 09 23:40:42 volumio volumio[851]: info: Exploding uri music-library/USB/288016118015E65A/阿凡达：水之道-2022_HDTC中英双字V2.mp4 in service mpd May 09 23:40:42 volumio volumio[851]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2F288016118015E65A%2F%E9%98%BF%E5%87%A1%E8%BE%BE%EF%BC%9A%E6%B0%B4%E4%B9%8B%E9%81%93-2022_HDTC%E4%B8%AD%E8%8B%B1%E5%8F%8C%E5%AD%97V2.mp4&metadata=false May 09 23:40:42 volumio volumio[851]: info: URI /mnt/USB/288016118015E65A/阿凡达：水之道-2022_HDTC中英双字V2.mp4 May 09 23:40:42 volumio volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 9 May 09 23:40:42 volumio volumio[851]: info: CoreCommandRouter::volumioGetState May 09 23:40:42 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:43 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:43 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 92. May 09 23:40:43 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:43 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:43 volumio go-librespot[3114]: Librespot-go daemon starting... May 09 23:40:43 volumio go-librespot[3114]: time="2024-05-09T23:40:43+08:00" level=info msg="generated new device id: df70e4fccc6e40ba8db16c9ee9a0333e61126bd9" May 09 23:40:43 volumio go-librespot[3114]: time="2024-05-09T23:40:43+08:00" level=debug msg="stored credentials not found" May 09 23:40:46 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:46 volumio go-librespot[3114]: time="2024-05-09T23:40:46+08:00" level=debug msg="new websocket client" May 09 23:40:46 volumio volumio[851]: info: Connection to go-librespot Websocket established May 09 23:40:49 volumio volumio[851]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/fa-tags.svg' May 09 23:40:49 volumio volumio[851]: info: Getting Spotify volume May 09 23:40:49 volumio volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 May 09 23:40:49 volumio volumio[851]: info: CoreCommandRouter::volumioGetState May 09 23:40:49 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:49 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:49 volumio volumio[851]: SPOTIFY: SPOTIFY VOLUME 100 May 09 23:40:49 volumio volumio[851]: SPOTIFY: VOLUMIO VOLUME 100 May 09 23:40:49 volumio volumio[851]: SPOTIFY: DELTA VOLUME ENOUGH: false May 09 23:40:51 volumio go-librespot[3114]: time="2024-05-09T23:40:51+08:00" level=debug msg="obtained new client token: AAB7o401VlNZHa8uGS/y2kdyP/I2NaNtcd5s0tGX82+OPqCJOh7kFu2yJsIA43DjJSLxRkhriwWIcJqAQLmc0ShZMWPrVt8KMqHhvL140QBHvfLu8fImi4PZu1ajmDYZ6Rim5qrkXhDBpiPr38ZbnhvOlDzsU5kdn2P+yFlA3LFd1q8eKQL2afBLKwgpcq++RV2tkrNEIfaqJJ5aYjzaeLLC8bseBzt2wW6flNZQwJxFzQrOJH2mRPW6b+VQ+Q==" May 09 23:40:51 volumio volumio[851]: info: VolumeController::SetAlsaVolume+ May 09 23:40:51 volumio volumio[851]: info: CoreStateMachine::pushState May 09 23:40:51 volumio volumio[851]: info: CorePlayQueue::getTrack 0 May 09 23:40:51 volumio volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 09 23:40:51 volumio volumio[851]: info: CoreCommandRouter::volumioPushState May 09 23:40:51 volumio volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 09 23:40:52 volumio go-librespot[3114]: time="2024-05-09T23:40:52+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]" May 09 23:40:52 volumio go-librespot[3114]: time="2024-05-09T23:40:52+08:00" level=debug msg="completed keyexchange" May 09 23:40:53 volumio go-librespot[3114]: time="2024-05-09T23:40:53+08:00" level=debug msg="completed challenge" May 09 23:40:53 volumio go-librespot[3114]: time="2024-05-09T23:40:53+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 09 23:40:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:53 volumio volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: socket hang up May 09 23:40:53 volumio volumio[851]: at connResetException (internal/errors.js:607:14) May 09 23:40:53 volumio volumio[851]: at Socket.socketOnEnd (_http_client.js:493:23) May 09 23:40:53 volumio volumio[851]: at Socket.emit (events.js:327:22) May 09 23:40:53 volumio volumio[851]: at endReadableNT (internal/streams/readable.js:1327:12) May 09 23:40:53 volumio volumio[851]: at processTicksAndRejections (internal/process/task_queues.js:80:21) May 09 23:40:53 volumio volumio[851]: (node:851) 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: 72) May 09 23:40:53 volumio volumio[851]: info: Connection to go-librespot Websocket closed May 09 23:40:56 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:56 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:56 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:40:56 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. May 09 23:40:56 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:40:56 volumio systemd[1]: Started go-librespot Daemon. May 09 23:40:56 volumio go-librespot[3123]: Librespot-go daemon starting... May 09 23:40:56 volumio go-librespot[3123]: time="2024-05-09T23:40:56+08:00" level=info msg="generated new device id: a9af9f71e92a4937e2efc2db37938cbee8159b16" May 09 23:40:56 volumio go-librespot[3123]: time="2024-05-09T23:40:56+08:00" level=debug msg="stored credentials not found" May 09 23:40:56 volumio go-librespot[3123]: time="2024-05-09T23:40:56+08:00" level=debug msg="obtained new client token: AACsforslI7kojxpClqoSt1kNQ3xE63jmYrSRS9Lu5yPfEj+HBSi+I2mt+i9M9dHVE/y5auMSMmSA2VpQYqnSQ8CIBFTFVYa4XNwvL786dFprhzdgJZWxK2B8DB44QPExicIHOd7LHH501Kk42GVdvXXyagJVP4TwwGokAScAnkGWihnT4AmSSeLDOV2h4X0mm3nSA4vaqPd6Y/idsk0rgWhv7OWVbEaoDeb4S4CWz2EhDxDkgvVOu/gKa2aLYMB" May 09 23:40:57 volumio go-librespot[3123]: time="2024-05-09T23:40:57+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]" May 09 23:40:57 volumio go-librespot[3123]: time="2024-05-09T23:40:57+08:00" level=debug msg="completed keyexchange" May 09 23:40:58 volumio go-librespot[3123]: time="2024-05-09T23:40:58+08:00" level=debug msg="completed challenge" May 09 23:40:58 volumio go-librespot[3123]: time="2024-05-09T23:40:58+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" May 09 23:40:58 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE May 09 23:40:58 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. May 09 23:40:59 volumio volumio[851]: info: Initializing connection to go-librespot Websocket May 09 23:40:59 volumio volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 May 09 23:40:59 volumio volumio[851]: info: peppy_screensaver: Start PeppyMeter May 09 23:41:01 volumio volumio[851]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 09 23:41:01 volumio volumio[851]: Error: connect ETIMEDOUT 168.143.162.58:80 May 09 23:41:01 volumio volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { May 09 23:41:01 volumio volumio[851]: errno: -110, May 09 23:41:01 volumio volumio[851]: code: 'ETIMEDOUT', May 09 23:41:01 volumio volumio[851]: syscall: 'connect', May 09 23:41:01 volumio volumio[851]: address: '168.143.162.58', May 09 23:41:01 volumio volumio[851]: port: 80 May 09 23:41:01 volumio volumio[851]: } May 09 23:41:01 volumio volumio[851]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 09 23:41:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. May 09 23:41:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 94. May 09 23:41:01 volumio systemd[1]: Stopped go-librespot Daemon. May 09 23:41:01 volumio systemd[1]: Started go-librespot Daemon. May 09 23:41:01 volumio go-librespot[3140]: Librespot-go daemon starting... May 09 23:41:01 volumio go-librespot[3140]: time="2024-05-09T23:41:01+08:00" level=info msg="generated new device id: 9baf63d6ec2ffb12a03ad87f4cabc05c76c7aeb8" May 09 23:41:01 volumio go-librespot[3140]: time="2024-05-09T23:41:01+08:00" level=debug msg="stored credentials not found" May 09 23:41:01 volumio sudo[3149]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-09 23:40 May 09 23:41:01 volumio sudo[3149]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"