-- Logs begin at Sun 2024-04-14 21:03:25 CST, end at Tue 2024-04-16 18:41:55 CST. -- Apr 16 18:40:01 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:01 volumio volumio[864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 18:40:01 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 18:40:01 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 123. Apr 16 18:40:01 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 18:40:02 volumio systemd[1]: Started go-librespot Daemon. Apr 16 18:40:02 volumio go-librespot[4442]: Librespot-go daemon starting... Apr 16 18:40:02 volumio go-librespot[4442]: time="2024-04-16T18:40:02+08:00" level=info msg="generated new device id: 8592b447f255e3057847bbf9bec4d5e6e33aca16" Apr 16 18:40:02 volumio go-librespot[4442]: time="2024-04-16T18:40:02+08:00" level=debug msg="stored credentials not found" Apr 16 18:40:04 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:04 volumio go-librespot[4442]: time="2024-04-16T18:40:04+08:00" level=debug msg="new websocket client" Apr 16 18:40:04 volumio volumio[864]: info: Connection to go-librespot Websocket established Apr 16 18:40:07 volumio volumio[864]: info: Getting Spotify volume Apr 16 18:40:07 volumio volumio[864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Apr 16 18:40:07 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:40:07 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:07 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:08 volumio volumio[864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 8 Apr 16 18:40:08 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:40:08 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:09 volumio volumio[864]: info: peppy_screensaver: Start PeppyMeter Apr 16 18:40:13 volumio go-librespot[4442]: time="2024-04-16T18:40:13+08:00" level=debug msg="obtained new client token: AACdkJeio1mgQzk4JgS/XWfVE6zZm0x1BBXqMtbKXOD37fzMyDwZV6MBdONrVGvwxhvfzfjdTQFVxPfSkU5d9TncfgeFsrGxwcXsKJ4jhcDngJZCLYJGXH7OTlcveSCzy5cGJrKCnTLJxZ8q9QiPapOYn8gQC8f9TkFabyEtv2csCMsX1PqpX/hiAgZUT6PqmNIqkS+YP2WRwj/cuc0JvG/i1rlG3H4vjMFPtDmTauniZuY8DKhC9kBF9yJ/" Apr 16 18:40:14 volumio volumio[864]: info: Preload queue cleared Apr 16 18:40:14 volumio volumio[864]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::ClearQueue Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::stop Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::stPlaybackTimer Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::updateTrackBlock Apr 16 18:40:14 volumio volumio[864]: info: CorePlayQueue::getTrackBlock Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:14 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:14 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 18:40:14 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::serviceStop Apr 16 18:40:14 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:14 volumio volumio[864]: info: CoreCommandRouter::serviceStop Apr 16 18:40:14 volumio volumio[864]: info: ControllerMpd::stop Apr 16 18:40:14 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 18:40:14 volumio volumio[864]: info: CorePlayQueue::clearPlayQueue Apr 16 18:40:14 volumio volumio[864]: info: CorePlayQueue::saveQueue Apr 16 18:40:14 volumio volumio[864]: info: CoreCommandRouter::volumioPushQueue Apr 16 18:40:14 volumio volumio[864]: info: CoreStateMachine::addQueueItems Apr 16 18:40:14 volumio volumio[864]: info: CorePlayQueue::addQueueItems Apr 16 18:40:14 volumio volumio[864]: info: Preload queue cleared Apr 16 18:40:14 volumio volumio[864]: info: Adding Item to queue: music-library/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带 Apr 16 18:40:14 volumio volumio[864]: info: Exploding uri music-library/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带 in service mpd Apr 16 18:40:14 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 16 18:40:14 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F01.%20%E4%B8%80%E7%9E%AC%E9%97%B4.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F02.%E9%9A%BE%E5%BF%98%E7%9A%84%E4%B8%80%E5%A4%A9.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/02.难忘的一天.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F03.%20%E6%88%91%E4%BC%9A%E6%83%B3%E8%B5%B7%E4%BD%A0.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/03. 我会想起你.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F04.%20%E9%9B%A8.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/04. 雨.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F05.%20%E4%BC%A0%E5%A5%87.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/05. 传奇.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F06.%20%E7%BA%A2%E8%94%B7%E8%96%87.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/06. 红蔷薇.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F07.%20%E6%B8%A9%E6%9A%96.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/07. 温暖.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F08.%20knoking%20on%20heaven's%20door.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/08. knoking on heaven's door.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F09.%20%E4%B8%8D%E5%86%8D%E5%AD%A4%E5%8D%95.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/09. 不再孤单.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F10.%20%E4%BA%B2%E7%88%B1%E7%9A%84%E6%9C%8B%E5%8F%8B.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/10. 亲爱的朋友.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F11.%20%E7%83%9F%E8%8A%B1%E7%BB%BD%E6%94%BE.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/11. 烟花绽放.wav Apr 16 18:40:15 volumio volumio[864]: info: ALBUMART /albumart?cacheid=379&web=%3F%3F%3F%3F/%3F%3F%3F%3FK2%3F%3F/extralarge&path=%2Fmnt%2FUSB%2FHIFI2%2FHIFI%E7%94%B7%E5%A5%B3%E5%A3%B0%2F02HIFI%E5%8F%91%E7%83%A7%E5%9B%BD%E8%AF%AD%E5%A5%B3%E5%A3%B0%2F%E4%B8%BD%E6%B1%9F%E5%B0%8F%E5%80%A9%20-%20%E8%AF%95%E9%9F%B3%E5%A4%A9%E7%A2%9FK2%E6%AF%8D%E5%B8%A6%2F12.%20%E6%88%91%E5%AF%B9%E4%BD%A0%E7%9A%84%E7%88%B1.wav&metadata=false Apr 16 18:40:15 volumio volumio[864]: info: URI /mnt/USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/12. 我对你的爱.wav Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand stop took 75 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushQueue Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::saveQueue Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::updateTrackBlock Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrackBlock Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPlay Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::play index 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::stop Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::play index undefined Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::startPlaybackTimer Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::clearAddPlayTracks USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand stop Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 32 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand stop took 20 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 16 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 15 milliseconds Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand clear Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces system playlist update Apr 16 18:40:15 volumio volumio[864]: info: Ignoring MPD Status Update Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 10 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand clear took 9 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 10 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand add "USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav" Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::pushState Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::servicePushState Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: 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":"01 ???????","artist":"Anne?? ","album":"??????","uri":"USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/Anne任芳 - 雨后初晴/01 这个秋天有点凉.wav","trackType":"wav"} Apr 16 18:40:15 volumio volumio[864]: verbose: CURRENT POSITION 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState stateService stop Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState currentStatus stop Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: No code Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 16 18:40:15 volumio volumio[864]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 111ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 85ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 84ms Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces system playlist update Apr 16 18:40:15 volumio volumio[864]: info: Ignoring MPD Status Update Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces system playlist update Apr 16 18:40:15 volumio volumio[864]: info: Ignoring MPD Status Update Apr 16 18:40:15 volumio volumio[864]: error: updateQueue error: null Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces system playlist update Apr 16 18:40:15 volumio volumio[864]: info: Ignoring MPD Status Update Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 147ms Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand add "USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav" took 143 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 88ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 88ms Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand play Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces system playlist update Apr 16 18:40:15 volumio volumio[864]: info: Ignoring MPD Status Update Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces system playlist update Apr 16 18:40:15 volumio volumio[864]: info: Ignoring MPD Status Update Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 29ms Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand play took 28 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 27ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 24ms Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 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 16 18:40:15 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 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 230 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 231 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 230 milliseconds Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: Apr 16 18:40:15 volumio volumio[864]: ---------------------------- MPD announces state update: player Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::getState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand status Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 9 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 9 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 4 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand status took 4 milliseconds Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseState Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::pushState Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::servicePushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":184,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???","artist":"????","album":"????K2??","uri":"USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav","trackType":"wav"} Apr 16 18:40:15 volumio volumio[864]: verbose: CURRENT POSITION 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState stateService play Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState currentStatus stop Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::pushState Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::servicePushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: verbose: STATE SERVICE {"status":"play","position":0,"seek":617,"duration":184,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???","artist":"????","album":"????K2??","uri":"USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav","trackType":"wav"} Apr 16 18:40:15 volumio volumio[864]: verbose: CURRENT POSITION 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState stateService play Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState currentStatus play Apr 16 18:40:15 volumio volumio[864]: info: Received an update from plugin. extracting info from payload Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::pushState Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::servicePushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: verbose: STATE SERVICE {"status":"play","position":0,"seek":617,"duration":184,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???","artist":"????","album":"????K2??","uri":"USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav","trackType":"wav"} Apr 16 18:40:15 volumio volumio[864]: verbose: CURRENT POSITION 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState stateService play Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState currentStatus play Apr 16 18:40:15 volumio volumio[864]: info: Received an update from plugin. extracting info from payload Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 262ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 287ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 286ms Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 50 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 49 milliseconds Apr 16 18:40:15 volumio volumio[864]: info: sendMpdCommand playlistinfo took 49 milliseconds Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: verbose: ControllerMpd::parseTrackInfo Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::pushState Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::servicePushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":184,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???","artist":"????","album":"????K2??","uri":"USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav","trackType":"wav"} Apr 16 18:40:15 volumio volumio[864]: verbose: CURRENT POSITION 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState stateService play Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState currentStatus play Apr 16 18:40:15 volumio volumio[864]: info: Received an update from plugin. extracting info from payload Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::pushState Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::servicePushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":184,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???","artist":"????","album":"????K2??","uri":"USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav","trackType":"wav"} Apr 16 18:40:15 volumio volumio[864]: verbose: CURRENT POSITION 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState stateService play Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState currentStatus play Apr 16 18:40:15 volumio volumio[864]: info: Received an update from plugin. extracting info from payload Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: ControllerMpd::pushState Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::servicePushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: verbose: STATE SERVICE {"status":"play","position":0,"seek":709,"duration":184,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"???","artist":"????","album":"????K2??","uri":"USB/HIFI2/HIFI男女声/02HIFI发烧国语女声/丽江小倩 - 试音天碟K2母带/01. 一瞬间.wav","trackType":"wav"} Apr 16 18:40:15 volumio volumio[864]: verbose: CURRENT POSITION 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState stateService play Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::syncState currentStatus play Apr 16 18:40:15 volumio volumio[864]: info: Received an update from plugin. extracting info from payload Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: CoreStateMachine::pushState Apr 16 18:40:15 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:15 volumio volumio[864]: info: CoreCommandRouter::volumioPushState Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 171ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 168ms Apr 16 18:40:15 volumio volumio[864]: info: ------------------------------ 165ms Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:15 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:17 volumio go-librespot[4442]: time="2024-04-16T18:40:17+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 16 18:40:19 volumio go-librespot[4442]: time="2024-04-16T18:40:19+08:00" level=debug msg="completed keyexchange" Apr 16 18:40:19 volumio go-librespot[4442]: time="2024-04-16T18:40:19+08:00" level=debug msg="completed challenge" Apr 16 18:40:20 volumio go-librespot[4442]: time="2024-04-16T18:40: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: BadCredentials" Apr 16 18:40:20 volumio volumio[864]: (node:864) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 16 18:40:20 volumio volumio[864]: at connResetException (internal/errors.js:607:14) Apr 16 18:40:20 volumio volumio[864]: at Socket.socketOnEnd (_http_client.js:493:23) Apr 16 18:40:20 volumio volumio[864]: at Socket.emit (events.js:327:22) Apr 16 18:40:20 volumio volumio[864]: at endReadableNT (internal/streams/readable.js:1327:12) Apr 16 18:40:20 volumio volumio[864]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Apr 16 18:40:20 volumio volumio[864]: (node:864) 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: 38) Apr 16 18:40:20 volumio volumio[864]: info: Connection to go-librespot Websocket closed Apr 16 18:40:20 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 18:40:20 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 18:40:23 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:23 volumio volumio[864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 18:40:23 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 18:40:23 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 124. Apr 16 18:40:23 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 18:40:24 volumio systemd[1]: Started go-librespot Daemon. Apr 16 18:40:24 volumio go-librespot[4530]: Librespot-go daemon starting... Apr 16 18:40:24 volumio go-librespot[4530]: time="2024-04-16T18:40:24+08:00" level=info msg="generated new device id: 06cc5e2a4719e9e6e48ee43e129d6c1f9ca74537" Apr 16 18:40:24 volumio go-librespot[4530]: time="2024-04-16T18:40:24+08:00" level=debug msg="stored credentials not found" Apr 16 18:40:26 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:26 volumio go-librespot[4530]: time="2024-04-16T18:40:26+08:00" level=debug msg="new websocket client" Apr 16 18:40:26 volumio volumio[864]: info: Connection to go-librespot Websocket established Apr 16 18:40:26 volumio ntpd[683]: Soliciting pool server 5.79.108.34 Apr 16 18:40:28 volumio ntpd[683]: Soliciting pool server 2a01:4f8:120:9224::2 Apr 16 18:40:29 volumio volumio[864]: info: Getting Spotify volume Apr 16 18:40:29 volumio volumio[864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Apr 16 18:40:29 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:40:29 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:29 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:30 volumio ntpd[683]: Soliciting pool server 84.16.67.12 Apr 16 18:40:31 volumio go-librespot[4530]: time="2024-04-16T18:40:31+08:00" level=debug msg="obtained new client token: AABHw+Fydd4mYutVrYB8w/IdnAQ00iSOTyntXyPQaRfqrt/vwy5X+2Ft1FIkvgNQqt+gFPc5kA/m5DZgWKFt0FWl1lZuz9wisI5IJbRaMpYdBv+E5xai1t2mJlQ5d8eORaoVIi0oPpJOzAvg6phY7EwToT607xt8EtAF2dD05ZDDmyBoNYOXyw4w+Utb+hV0mPGV2SNL+g1lpVpzyQ4iQz5IYyV2K/RuKrI3Sz7W0UdQj2z3+VHrpR+3faSH" Apr 16 18:40:32 volumio volumio[864]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 16 18:40:32 volumio volumio[864]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 16 18:40:33 volumio ntpd[683]: Soliciting pool server 78.46.102.180 Apr 16 18:40:33 volumio volumio[864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 8 Apr 16 18:40:33 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:40:33 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:42 volumio go-librespot[4530]: time="2024-04-16T18:40:42+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 16 18:40:42 volumio go-librespot[4530]: time="2024-04-16T18:40:42+08:00" level=debug msg="completed keyexchange" Apr 16 18:40:42 volumio go-librespot[4530]: time="2024-04-16T18:40:42+08:00" level=debug msg="completed challenge" Apr 16 18:40:42 volumio go-librespot[4530]: time="2024-04-16T18:40:42+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 16 18:40:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 18:40:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 18:40:42 volumio volumio[864]: (node:864) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 16 18:40:42 volumio volumio[864]: at connResetException (internal/errors.js:607:14) Apr 16 18:40:42 volumio volumio[864]: at Socket.socketOnEnd (_http_client.js:493:23) Apr 16 18:40:42 volumio volumio[864]: at Socket.emit (events.js:327:22) Apr 16 18:40:42 volumio volumio[864]: at endReadableNT (internal/streams/readable.js:1327:12) Apr 16 18:40:42 volumio volumio[864]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Apr 16 18:40:42 volumio volumio[864]: (node:864) 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: 39) Apr 16 18:40:42 volumio volumio[864]: info: Connection to go-librespot Websocket closed Apr 16 18:40:45 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:45 volumio volumio[864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 18:40:45 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 18:40:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 125. Apr 16 18:40:45 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 18:40:46 volumio systemd[1]: Started go-librespot Daemon. Apr 16 18:40:46 volumio go-librespot[4573]: Librespot-go daemon starting... Apr 16 18:40:46 volumio go-librespot[4573]: time="2024-04-16T18:40:46+08:00" level=info msg="generated new device id: 694fa8866384a1a64bcd2d89ecbf60b34bef3a27" Apr 16 18:40:46 volumio go-librespot[4573]: time="2024-04-16T18:40:46+08:00" level=debug msg="stored credentials not found" Apr 16 18:40:48 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:48 volumio volumio[864]: info: Connection to go-librespot Websocket established Apr 16 18:40:48 volumio go-librespot[4573]: time="2024-04-16T18:40:48+08:00" level=debug msg="new websocket client" Apr 16 18:40:49 volumio go-librespot[4573]: time="2024-04-16T18:40:49+08:00" level=debug msg="obtained new client token: AADF60QvyFHW6VVPLEVd3eRyKAkb9zWE3A8SPMzMTMxoc0I98/0N4kUDcCkyDzUERlfQR553BQX6hoRsCz8F4dh9M6ZdN0F+VvCYpTws8XIYXpHawfyejy/I5QmdH9pZN+ARrMQsrM9nqn9oDIfYHq0I4qgF78FWR9Jp3rRKY3IOHFuA5XSgkzzZT9mPK2l7JCJHT6fkA9WsNt/5s15PxnNQS9qFI/yIh8Qh3Q5N5N3efJ/mZNzWxHq2OzUP" Apr 16 18:40:49 volumio go-librespot[4573]: time="2024-04-16T18:40:49+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 16 18:40:50 volumio go-librespot[4573]: time="2024-04-16T18:40:50+08:00" level=debug msg="completed keyexchange" Apr 16 18:40:50 volumio go-librespot[4573]: time="2024-04-16T18:40:50+08:00" level=debug msg="completed challenge" Apr 16 18:40:50 volumio go-librespot[4573]: time="2024-04-16T18:40: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: BadCredentials" Apr 16 18:40:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 18:40:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 18:40:50 volumio volumio[864]: info: Connection to go-librespot Websocket closed Apr 16 18:40:51 volumio volumio[864]: info: Getting Spotify volume Apr 16 18:40:51 volumio volumio[864]: (node:864) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 18:40:51 volumio volumio[864]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 16 18:40:51 volumio volumio[864]: (node:864) 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: 40) Apr 16 18:40:51 volumio volumio[864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 16 18:40:51 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:40:51 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:51 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:40:53 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:53 volumio volumio[864]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 16 18:40:53 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 18:40:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 126. Apr 16 18:40:53 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 18:40:53 volumio systemd[1]: Started go-librespot Daemon. Apr 16 18:40:53 volumio go-librespot[4581]: Librespot-go daemon starting... Apr 16 18:40:53 volumio go-librespot[4581]: time="2024-04-16T18:40:53+08:00" level=info msg="generated new device id: 2341831f75cc5ccbb79621e0a03390ad881bc6c9" Apr 16 18:40:53 volumio go-librespot[4581]: time="2024-04-16T18:40:53+08:00" level=debug msg="stored credentials not found" Apr 16 18:40:56 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:40:56 volumio go-librespot[4581]: time="2024-04-16T18:40:56+08:00" level=debug msg="new websocket client" Apr 16 18:40:56 volumio volumio[864]: info: Connection to go-librespot Websocket established Apr 16 18:40:59 volumio volumio[864]: info: Getting Spotify volume Apr 16 18:40:59 volumio volumio[864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 16 18:40:59 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:40:59 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:40:59 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:41:15 volumio go-librespot[4581]: time="2024-04-16T18:41:15+08:00" level=debug msg="obtained new client token: AABquwSIv5vSQxqX6OPaI1RdyWGt1cg/k3XmimsHjEiB6Ld3VARMGhpdUAF78gBknKpOIu/LPXbGGTgqaQqFqFRQM2HxQarPDRNRMzk/bPnkGrLVOv99iS4zfAfctYQusP+4jQsRO+LrNYpZvIzxB59OZadi9jdJcs7isxqdmCI8yisg060xN5W/MuUy8H0ZHmyk/l3/ogHD3kg52VbPN6VUPtRUcDhX94/WDXkQod19DfDryeXPWFuYtu2b" Apr 16 18:41:20 volumio go-librespot[4581]: time="2024-04-16T18:41: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]" Apr 16 18:41:22 volumio go-librespot[4581]: time="2024-04-16T18:41:22+08:00" level=debug msg="completed keyexchange" Apr 16 18:41:23 volumio go-librespot[4581]: time="2024-04-16T18:41:23+08:00" level=debug msg="completed challenge" Apr 16 18:41:23 volumio go-librespot[4581]: time="2024-04-16T18:41:23+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Apr 16 18:41:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 16 18:41:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 16 18:41:23 volumio volumio[864]: (node:864) UnhandledPromiseRejectionWarning: Error: socket hang up Apr 16 18:41:23 volumio volumio[864]: at connResetException (internal/errors.js:607:14) Apr 16 18:41:23 volumio volumio[864]: at Socket.socketOnEnd (_http_client.js:493:23) Apr 16 18:41:23 volumio volumio[864]: at Socket.emit (events.js:327:22) Apr 16 18:41:23 volumio volumio[864]: at endReadableNT (internal/streams/readable.js:1327:12) Apr 16 18:41:23 volumio volumio[864]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Apr 16 18:41:23 volumio volumio[864]: (node:864) 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: 41) Apr 16 18:41:23 volumio volumio[864]: info: Connection to go-librespot Websocket closed Apr 16 18:41:25 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 18:41:25 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 18:41:25 volumio volumio[864]: info: Discovery: Getting this device information Apr 16 18:41:25 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:41:25 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:41:25 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 18:41:26 volumio volumio[864]: info: Initializing connection to go-librespot Websocket Apr 16 18:41:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 16 18:41:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 127. Apr 16 18:41:26 volumio systemd[1]: Stopped go-librespot Daemon. Apr 16 18:41:27 volumio systemd[1]: Started go-librespot Daemon. Apr 16 18:41:27 volumio go-librespot[4632]: Librespot-go daemon starting... Apr 16 18:41:27 volumio go-librespot[4632]: time="2024-04-16T18:41:27+08:00" level=info msg="generated new device id: 22f4b6e39cf2b9495f3d24d8975d82d5e8cc0a65" Apr 16 18:41:27 volumio go-librespot[4632]: time="2024-04-16T18:41:27+08:00" level=debug msg="stored credentials not found" Apr 16 18:41:31 volumio go-librespot[4632]: time="2024-04-16T18:41:31+08:00" level=debug msg="new websocket client" Apr 16 18:41:31 volumio volumio[864]: info: Connection to go-librespot Websocket established Apr 16 18:41:34 volumio volumio[864]: info: Getting Spotify volume Apr 16 18:41:34 volumio volumio[864]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 16 18:41:34 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:41:34 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:41:34 volumio volumio[864]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 16 18:41:37 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 16 18:41:37 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 16 18:41:37 volumio volumio[864]: info: Discovery: Getting this device information Apr 16 18:41:37 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:41:37 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:41:37 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 16 18:41:38 volumio volumio[864]: verbose: New Socket.io Connection to 192.168.10.2 from 192.168.10.7 UA: unknown Total Clients: 9 Apr 16 18:41:38 volumio volumio[864]: info: CoreCommandRouter::volumioGetState Apr 16 18:41:38 volumio volumio[864]: info: CorePlayQueue::getTrack 0 Apr 16 18:41:38 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 16 18:41:38 volumio volumio[864]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 16 18:41:55 volumio volumio[864]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 18:41:55 volumio volumio[864]: Error: connect ETIMEDOUT 31.13.70.9:80 Apr 16 18:41:55 volumio volumio[864]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Apr 16 18:41:55 volumio volumio[864]: errno: -110, Apr 16 18:41:55 volumio volumio[864]: code: 'ETIMEDOUT', Apr 16 18:41:55 volumio volumio[864]: syscall: 'connect', Apr 16 18:41:55 volumio volumio[864]: address: '31.13.70.9', Apr 16 18:41:55 volumio volumio[864]: port: 80 Apr 16 18:41:55 volumio volumio[864]: } Apr 16 18:41:55 volumio volumio[864]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 16 18:41:55 volumio sudo[4653]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-16 18:40 Apr 16 18:41:55 volumio sudo[4653]: 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"