-- Logs begin at Tue 2024-07-09 19:08:03 CST, end at Thu 2024-08-22 13:37:00 CST. -- Aug 22 13:36:00 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:00 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 93. Aug 22 13:36:00 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:00 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:00 volumio1 go-librespot[3066]: Librespot-go daemon starting... Aug 22 13:36:00 volumio1 go-librespot[3066]: time="2024-08-22T13:36:00+08:00" level=info msg="generated new device id: da5a565d59a82dd13f60dc90ad658e7975b03403" Aug 22 13:36:00 volumio1 go-librespot[3066]: time="2024-08-22T13:36:00+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:00 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:00 volumio1 go-librespot[3066]: time="2024-08-22T13:36:00+08:00" level=debug msg="new websocket client" Aug 22 13:36:00 volumio1 volumio[1109]: info: Connection to go-librespot Websocket established Aug 22 13:36:00 volumio1 go-librespot[3066]: time="2024-08-22T13:36:00+08:00" level=debug msg="obtained new client token: AADqsjUjEFVR6EsREnnD7pZgh4dowcDfWB56O3SJS8kKruw9kYI1p8Xo/U4HpvbXNeu6VChM9vMmcTacLfkKZrUT1r2qM1gwlIVKZ+cnocm7Ukny8EvDO8WIuqxocaZSVYQuW9c5ppUW7EQ6JHpM51OVuzhOKgCwfKXrVfu2cGoVDxjy4cWhHd5sP8yLA5GGtD/vQoRrZy9/XAQ/b9t3Cb2IOSU8m9BOypm+IR/kLy4jzAyA6yLWNcGQly7pAw==" Aug 22 13:36:01 volumio1 go-librespot[3066]: time="2024-08-22T13:36:01+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]" Aug 22 13:36:01 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:01 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 4 Aug 22 13:36:01 volumio1 go-librespot[3066]: time="2024-08-22T13:36:01+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:02 volumio1 go-librespot[3066]: time="2024-08-22T13:36:02+08:00" level=debug msg="completed challenge" Aug 22 13:36:02 volumio1 go-librespot[3066]: time="2024-08-22T13:36:02+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:02 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:02 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:02 volumio1 volumio[1109]: info: Connection to go-librespot Websocket closed Aug 22 13:36:02 volumio1 volumio[1109]: info: Preload queue cleared Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::ClearQueue Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::stop Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::updateTrackBlock Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrackBlock Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 4 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::serviceStop Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 4 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::serviceStop Aug 22 13:36:02 volumio1 volumio[1109]: info: ControllerMpd::stop Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand stop Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::clearPlayQueue Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::saveQueue Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushQueue Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::addQueueItems Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::addQueueItems Aug 22 13:36:02 volumio1 volumio[1109]: info: Preload queue cleared Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Bear McCreary-Anacreon.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Bear McCreary-Anacreon.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Sunstroke Project-Hey Mamma(Radio Edit).flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Sunstroke Project-Hey Mamma(Radio Edit).flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Tommee Profitt-O Come O Come Emmanuel.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Tommee Profitt-O Come O Come Emmanuel.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Audiomachine&ANEW-The Grotto(DJ Anew版).mp3 Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Audiomachine&ANEW-The Grotto(DJ Anew版).mp3 Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/FreshmanSound-Fear.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/FreshmanSound-Fear.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3 Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3 Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 22 13:36:02 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 22 13:36:02 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushQueue Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::saveQueue Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::updateTrackBlock Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrackBlock Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPlay Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::play index 3 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::stop Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::play index undefined Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::startPlaybackTimer Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::clearAddPlayTracks USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand stop Aug 22 13:36:02 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:02 volumio1 volumio[1109]: info: Aug 22 13:36:02 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:02 volumio1 volumio[1109]: info: sendMpdCommand stop took 68 milliseconds Aug 22 13:36:02 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:02 volumio1 volumio[1109]: info: sendMpdCommand stop took 26 milliseconds Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand clear Aug 22 13:36:02 volumio1 volumio[1109]: info: Aug 22 13:36:02 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:02 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:02 volumio1 volumio[1109]: info: Aug 22 13:36:02 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:02 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:02 volumio1 volumio[1109]: info: Aug 22 13:36:02 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:02 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:02 volumio1 volumio[1109]: info: Aug 22 13:36:02 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:02 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:02 volumio1 volumio[1109]: info: sendMpdCommand status took 23 milliseconds Aug 22 13:36:02 volumio1 volumio[1109]: info: sendMpdCommand clear took 22 milliseconds Aug 22 13:36:02 volumio1 volumio[1109]: info: sendMpdCommand status took 20 milliseconds Aug 22 13:36:02 volumio1 volumio[1109]: info: sendMpdCommand status took 18 milliseconds Aug 22 13:36:02 volumio1 volumio[1109]: info: sendMpdCommand status took 15 milliseconds Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand add "USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac" Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:02 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:02 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:02 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:02 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:02 volumio1 volumio[1109]: info: No code Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:02 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:02 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:02 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: No code Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: No code Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 196ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 195ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 194ms Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:03 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:03 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:03 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:03 volumio1 volumio[1109]: error: updateQueue error: null Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:03 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 210ms Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 204 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand add "USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac" took 204 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 27ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 25ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 23ms Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand play Aug 22 13:36:03 volumio1 volumio[1109]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 250ms Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:03 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:03 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:03 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 91ms Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand play took 86 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 85ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 83ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 80ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 22 13:36:03 volumio1 volumio[1109]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 22 13:36:03 volumio1 volumio[1109]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 22 13:36:03 volumio1 volumio[1109]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/The%20Irrepressibles/Mirror%20Mirror/98f1e2b2-4e74-4cd2-93e4-2e29f27e45f1.png' Aug 22 13:36:03 volumio1 volumio[1109]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/The%20Irrepressibles/Mirror%20Mirror/98f1e2b2-4e74-4cd2-93e4-2e29f27e45f1.png' Aug 22 13:36:03 volumio1 volumio[1109]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/The%20Irrepressibles/Mirror%20Mirror/98f1e2b2-4e74-4cd2-93e4-2e29f27e45f1.png' Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 35 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 34 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 27 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 25 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 23 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: info: Aug 22 13:36:03 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 35 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 34 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 34 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 34 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 33 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 28 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 26 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand status took 23 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:03 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:03 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:03 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:03 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 137ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 244ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 235ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 234ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 233ms Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 190 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 185 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 185 milliseconds Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:03 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:03 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":960,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"894 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:03 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:03 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 350ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 348ms Aug 22 13:36:03 volumio1 volumio[1109]: info: ------------------------------ 346ms Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:03 volumio1 volumio[1109]: info: Getting Spotify volume Aug 22 13:36:03 volumio1 volumio[1109]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 22 13:36:03 volumio1 volumio[1109]: (node:1109) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:03 volumio1 volumio[1109]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 22 13:36:03 volumio1 volumio[1109]: (node:1109) 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: 37) Aug 22 13:36:03 volumio1 volumio[1109]: info: camilladsp spawned new process with pid 3084, instance 1, run: true Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/The%20Irrepressibles/Mirror%20Mirror/98f1e2b2-4e74-4cd2-93e4-2e29f27e45f1.png' Aug 22 13:36:03 volumio1 volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: Preload queue cleared Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::ClearQueue Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::stop Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::updateTrackBlock Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrackBlock Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::serviceStop Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::serviceStop Aug 22 13:36:03 volumio1 volumio[1109]: info: ControllerMpd::stop Aug 22 13:36:03 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand stop Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::clearPlayQueue Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::saveQueue Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushQueue Aug 22 13:36:03 volumio1 volumio[1109]: info: CoreStateMachine::addQueueItems Aug 22 13:36:03 volumio1 volumio[1109]: info: CorePlayQueue::addQueueItems Aug 22 13:36:03 volumio1 volumio[1109]: info: Preload queue cleared Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Bear McCreary-Anacreon.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Bear McCreary-Anacreon.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Sunstroke Project-Hey Mamma(Radio Edit).flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Sunstroke Project-Hey Mamma(Radio Edit).flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Tommee Profitt-O Come O Come Emmanuel.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Tommee Profitt-O Come O Come Emmanuel.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Audiomachine&ANEW-The Grotto(DJ Anew版).mp3 Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Audiomachine&ANEW-The Grotto(DJ Anew版).mp3 Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/FreshmanSound-Fear.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/FreshmanSound-Fear.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3 Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3 Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 22 13:36:03 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 22 13:36:03 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushQueue Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::saveQueue Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::updateTrackBlock Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrackBlock Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPlay Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::play index 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::stop Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::play index undefined Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::startPlaybackTimer Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::clearAddPlayTracks USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand stop Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand stop took 79 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand stop took 29 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand clear Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 30 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand clear took 29 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 28 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 25 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 24 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand add "USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac" Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: No code Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: No code Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: No code Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 203ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 203ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 202ms Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: error: updateQueue error: null Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 218ms Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 213 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand add "USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac" took 213 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 36ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 34ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 32ms Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand play Aug 22 13:36:04 volumio1 volumio[1109]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 254ms Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:04 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:04 volumio1 volumio[1109]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/The%20Irrepressibles/Mirror%20Mirror/98f1e2b2-4e74-4cd2-93e4-2e29f27e45f1.png' Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 46ms Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand play took 40 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 39ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 38ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 35ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 22 13:36:04 volumio1 volumio[1109]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 22 13:36:04 volumio1 volumio[1109]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 46 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 45 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 42 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 40 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 38 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: Aug 22 13:36:04 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 66 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 66 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 65 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 64 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 64 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 58 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 55 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand status took 51 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:04 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:04 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:04 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:04 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 210ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 364ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 358ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 356ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 355ms Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 242 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 242 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 241 milliseconds Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:04 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:04 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1098,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"858 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:04 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:04 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:04 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:04 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 414ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 411ms Aug 22 13:36:04 volumio1 volumio[1109]: info: ------------------------------ 408ms Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:04 volumio1 volumio[1109]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 22 13:36:04 volumio1 volumio[1109]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/The%20Irrepressibles/Mirror%20Mirror/98f1e2b2-4e74-4cd2-93e4-2e29f27e45f1.png' Aug 22 13:36:05 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:05 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:05 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:05 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:05 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:05 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 94. Aug 22 13:36:05 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:05 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:05 volumio1 go-librespot[3139]: Librespot-go daemon starting... Aug 22 13:36:05 volumio1 go-librespot[3139]: time="2024-08-22T13:36:05+08:00" level=info msg="generated new device id: b84c5f7a0c4f2c97263afd564bbdaa60daec3a2c" Aug 22 13:36:05 volumio1 go-librespot[3139]: time="2024-08-22T13:36:05+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:06 volumio1 go-librespot[3139]: time="2024-08-22T13:36:06+08:00" level=debug msg="obtained new client token: AAAFR4BCaDthu8ZKOeI5ewOXDKvCJML2dTeOp9ns0zuEqJwZNZeMSyYlWCb6QvA6Vh3fLTojS8A+ioEivopG7TInjiOVJ+rEh7hOG/o8fEXKjoyA2GlO+1Pdybo1RoMWu8tEy7ihGzlGAtVyCheE1Vq0cnxkbGrdUrGq47oKrwQB3HJdri9icro6Kz7BNt3N/igEq+p8MIx91ZGd8fVFlKg5RW14loQty95N9IXH4eGGq+0cfsAQRYhUoxp4pQ==" Aug 22 13:36:06 volumio1 go-librespot[3139]: time="2024-08-22T13:36:06+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]" Aug 22 13:36:06 volumio1 go-librespot[3139]: time="2024-08-22T13:36:06+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:07 volumio1 go-librespot[3139]: time="2024-08-22T13:36:07+08:00" level=debug msg="completed challenge" Aug 22 13:36:07 volumio1 go-librespot[3139]: time="2024-08-22T13:36:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:07 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:07 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:07 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:07 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:07 volumio1 volumio[1109]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 22 13:36:07 volumio1 volumio[1109]: info: Retrying Login Due to Network Error Aug 22 13:36:08 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:08 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:09 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:09 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:10 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:10 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 95. Aug 22 13:36:10 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:10 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:10 volumio1 go-librespot[3157]: Librespot-go daemon starting... Aug 22 13:36:10 volumio1 go-librespot[3157]: time="2024-08-22T13:36:10+08:00" level=info msg="generated new device id: c22bbe52c2e6612ac1b12c2e881b9e5b9027f8f1" Aug 22 13:36:10 volumio1 go-librespot[3157]: time="2024-08-22T13:36:10+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:10 volumio1 go-librespot[3157]: time="2024-08-22T13:36:10+08:00" level=debug msg="obtained new client token: AACWWsbLkbr/91sB3xdalQPKBiZL0HFem/It6hVIyCG1zHBF/zg3S7yJJhSxk8ydx8pFYESfjkRqvyiF8sphKuZqKDFraanIJuv/YVI99CpZRYOpK9g6sFPVlklYnlCRLBwmVWP7TDibOI4vBnGy9qqmoivPvdMWsHQOBg4VRbZw6j2ANlyndAKbWNMijk3r3SIlSCetzSRK1gpkBR1Z1IqPy+ZIRfR28HDggFMJcpM38hbB3Bo+yObDyXCiBQ==" Aug 22 13:36:10 volumio1 go-librespot[3157]: time="2024-08-22T13:36:10+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Aug 22 13:36:11 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:11 volumio1 go-librespot[3157]: time="2024-08-22T13:36:11+08:00" level=debug msg="new websocket client" Aug 22 13:36:11 volumio1 volumio[1109]: info: Connection to go-librespot Websocket established Aug 22 13:36:11 volumio1 go-librespot[3157]: time="2024-08-22T13:36:11+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::servicePause Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::servicePause Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::pause Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand pause Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand pause took 1 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: info: Aug 22 13:36:11 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:11 volumio1 volumio[1109]: info: Aug 22 13:36:11 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:11 volumio1 volumio[1109]: info: Aug 22 13:36:11 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:11 volumio1 volumio[1109]: info: Aug 22 13:36:11 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand status took 8 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand status took 7 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand status took 6 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand status took 4 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 5 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 6 milliseconds Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:11 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":8465,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"835 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:11 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":8465,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"835 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:11 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":8465,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"835 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:11 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:11 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":8465,"duration":335,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"835 Kbps","isStreaming":false,"title":"In This Shirt","artist":"The Irrepressibles","album":"Mirror Mirror","uri":"USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac","trackType":"flac"} Aug 22 13:36:11 volumio1 volumio[1109]: verbose: CURRENT POSITION 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus pause Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:11 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:11 volumio1 volumio[1109]: info: ------------------------------ 118ms Aug 22 13:36:11 volumio1 volumio[1109]: info: ------------------------------ 117ms Aug 22 13:36:11 volumio1 volumio[1109]: info: ------------------------------ 115ms Aug 22 13:36:11 volumio1 volumio[1109]: info: ------------------------------ 114ms Aug 22 13:36:11 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:11 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:11 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:11 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:11 volumio1 go-librespot[3157]: time="2024-08-22T13:36:11+08:00" level=debug msg="completed challenge" Aug 22 13:36:12 volumio1 go-librespot[3157]: time="2024-08-22T13:36:12+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:12 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:12 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:12 volumio1 volumio[1109]: info: Connection to go-librespot Websocket closed Aug 22 13:36:12 volumio1 volumio[1109]: info: camilladsp spawned new process with pid 3169, instance 1, run: true Aug 22 13:36:13 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:13 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:14 volumio1 volumio[1109]: info: Getting Spotify volume Aug 22 13:36:14 volumio1 volumio[1109]: (node:1109) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:14 volumio1 volumio[1109]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 22 13:36:14 volumio1 volumio[1109]: (node:1109) 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) Aug 22 13:36:14 volumio1 volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 22 13:36:14 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:14 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:14 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:15 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:15 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:15 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:15 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 96. Aug 22 13:36:15 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:15 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:15 volumio1 go-librespot[3176]: Librespot-go daemon starting... Aug 22 13:36:15 volumio1 go-librespot[3176]: time="2024-08-22T13:36:15+08:00" level=info msg="generated new device id: a8786759ccadae3fe345f1e8676cfc5f83a7d4e7" Aug 22 13:36:15 volumio1 go-librespot[3176]: time="2024-08-22T13:36:15+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:15 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:15 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:15 volumio1 go-librespot[3176]: time="2024-08-22T13:36:15+08:00" level=debug msg="obtained new client token: AACQsJ5qR7e8rpa7P6/fv9haPkXZDdnHRcoBeOpmhJG/vw0hEQ/SzqsSMDaD9O+HlCAJ2U9iCFWoFj9oD7nENwCn6A8I7j8NNmzKiFJMJT17JVHl72TualMuoeXSX0Ey8YmfhagvSC6YyvpgpH1pM4P2xeIXk1JON0BLeY7dGfMGzOIEbTAYt7EQeWFM8XjTXW0cuihys5Q+MSCmwhsg8OyzgKwjUnHRu87lvDpmbBODa5L/lO2QZizEn5Ag8Q==" Aug 22 13:36:16 volumio1 go-librespot[3176]: time="2024-08-22T13:36:16+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 22 13:36:16 volumio1 go-librespot[3176]: time="2024-08-22T13:36:16+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:16 volumio1 go-librespot[3176]: time="2024-08-22T13:36:16+08:00" level=debug msg="completed challenge" Aug 22 13:36:17 volumio1 go-librespot[3176]: time="2024-08-22T13:36:17+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:17 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:17 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:17 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:17 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:17 volumio1 volumio[1109]: info: MyVolumio login type: Token Aug 22 13:36:18 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:18 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:19 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:19 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:20 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:20 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 97. Aug 22 13:36:20 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:20 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:20 volumio1 go-librespot[3185]: Librespot-go daemon starting... Aug 22 13:36:20 volumio1 go-librespot[3185]: time="2024-08-22T13:36:20+08:00" level=info msg="generated new device id: 45d2f0af672ae310903f09186682e8df1eac8287" Aug 22 13:36:20 volumio1 go-librespot[3185]: time="2024-08-22T13:36:20+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:20 volumio1 go-librespot[3185]: time="2024-08-22T13:36:20+08:00" level=debug msg="obtained new client token: AADwnIzz0uozSIsLW87/G8xqtpzyu8GHNnsJWYpcawhDnWM1Q+4Gragg3KgbimHQQwbvJy0uMSVKj5cT4IEEOaWrUR/7/3U1eE6A26mMvpRAgWhfx2f6tGgqnxRhoArqjF/bzQ9fmCfhzFIjfeBnCej3O/yOK58pd5kOMU8+hTnubqUMvOUwOePe5DCEgbb9/7JhXw4qyHU6YHamQDiLl1PvC1w5rIcvNqlfpKTF67k77y0SRDd6HCxIOrloFg==" Aug 22 13:36:20 volumio1 go-librespot[3185]: time="2024-08-22T13:36: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]" Aug 22 13:36:21 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:21 volumio1 go-librespot[3185]: time="2024-08-22T13:36:21+08:00" level=debug msg="new websocket client" Aug 22 13:36:21 volumio1 volumio[1109]: info: Connection to go-librespot Websocket established Aug 22 13:36:21 volumio1 go-librespot[3185]: time="2024-08-22T13:36:21+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:21 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:21 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:21 volumio1 go-librespot[3185]: time="2024-08-22T13:36:21+08:00" level=debug msg="completed challenge" Aug 22 13:36:21 volumio1 go-librespot[3185]: time="2024-08-22T13:36:21+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:21 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:21 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:21 volumio1 volumio[1109]: info: Connection to go-librespot Websocket closed Aug 22 13:36:23 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:23 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:24 volumio1 volumio[1109]: info: Getting Spotify volume Aug 22 13:36:24 volumio1 volumio[1109]: (node:1109) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:24 volumio1 volumio[1109]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 22 13:36:24 volumio1 volumio[1109]: (node:1109) 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) Aug 22 13:36:24 volumio1 volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 22 13:36:24 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:24 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:24 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:24 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:24 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:25 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:25 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Aug 22 13:36:25 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:25 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:25 volumio1 go-librespot[3193]: Librespot-go daemon starting... Aug 22 13:36:25 volumio1 go-librespot[3193]: time="2024-08-22T13:36:25+08:00" level=info msg="generated new device id: c18c8937155379781f655de3701b8e8ba83bc1ae" Aug 22 13:36:25 volumio1 go-librespot[3193]: time="2024-08-22T13:36:25+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:25 volumio1 go-librespot[3193]: time="2024-08-22T13:36:25+08:00" level=debug msg="obtained new client token: AADwWsOn5nKjFgwsQWZX1j9QwfOltPiPiJHFOjpXtEFV0lj9jXuYWj5TMaptI0D4pAcEkcytGYZwVOWI3/LlNxPi76SNqeT0c1IPDps/SW/UxZo2Yf7OO/pFeVKstXCjMzOK4JBHXJC9MKMZ01kSL9v81G9Iqz6QgS+kj/iqEC3bSzwsZqX6cqh6WjSGAD/Vrjk48WA7HvXkS7DSAnBWtGc7EVltfJUGUxSZa/MWktgLLTjyxcMSCxRNDLbDvg==" Aug 22 13:36:25 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:25 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:25 volumio1 go-librespot[3193]: time="2024-08-22T13:36: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]" Aug 22 13:36:26 volumio1 go-librespot[3193]: time="2024-08-22T13:36:26+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:26 volumio1 go-librespot[3193]: time="2024-08-22T13:36:26+08:00" level=debug msg="completed challenge" Aug 22 13:36:26 volumio1 go-librespot[3193]: time="2024-08-22T13:36:26+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:26 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:26 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:27 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:27 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:27 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:27 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:29 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:29 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:29 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:29 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Aug 22 13:36:29 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:29 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:29 volumio1 go-librespot[3202]: Librespot-go daemon starting... Aug 22 13:36:29 volumio1 go-librespot[3202]: time="2024-08-22T13:36:29+08:00" level=info msg="generated new device id: 8428cbfee2d523a51e1a18be129aafcb79644c8d" Aug 22 13:36:29 volumio1 go-librespot[3202]: time="2024-08-22T13:36:29+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:30 volumio1 go-librespot[3202]: time="2024-08-22T13:36:30+08:00" level=debug msg="obtained new client token: AAAYXjtAXM8VQVL3tdFUqqOr6QJhvletqmthATpiwtIdnuiRwLhzrmDM4OhlgE8FVrZXNyNwKvnDTVSMjOy3xUTJQ0aNKx6odi68caWd9M9UXCzfAne3XcHko2tlf70D5U9y/tY7GmRJgwUJyM0Xk6TIntVh4tbt61cR8NQOJo7gfmfgRWPB+hNCDhpNW6RUGjM6kr+aTpRLxmcHAgM6BuRXq1TPRXfi22nNCYBti+RcSwfQBklztSPfTAw=" Aug 22 13:36:30 volumio1 go-librespot[3202]: time="2024-08-22T13:36:30+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]" Aug 22 13:36:30 volumio1 go-librespot[3202]: time="2024-08-22T13:36:30+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:31 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:31 volumio1 go-librespot[3202]: time="2024-08-22T13:36:31+08:00" level=debug msg="new websocket client" Aug 22 13:36:31 volumio1 volumio[1109]: info: Connection to go-librespot Websocket established Aug 22 13:36:31 volumio1 go-librespot[3202]: time="2024-08-22T13:36:31+08:00" level=debug msg="completed challenge" Aug 22 13:36:31 volumio1 go-librespot[3202]: time="2024-08-22T13:36:31+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:31 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:31 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:31 volumio1 volumio[1109]: info: Connection to go-librespot Websocket closed Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:31 volumio1 volumio[1109]: info: Preload queue cleared Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::ClearQueue Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::updateTrackBlock Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrackBlock Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::stPlaybackTimer Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::serviceStop Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 3 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::serviceStop Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::stop Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::clearPlayQueue Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::saveQueue Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushQueue Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::addQueueItems Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::addQueueItems Aug 22 13:36:31 volumio1 volumio[1109]: info: Preload queue cleared Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/ZABO-Drown.FLAC Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Bear McCreary-Anacreon.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Bear McCreary-Anacreon.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Sunstroke Project-Hey Mamma(Radio Edit).flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Sunstroke Project-Hey Mamma(Radio Edit).flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/The Irrepressibles-In This Shirt.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Tommee Profitt-O Come O Come Emmanuel.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Tommee Profitt-O Come O Come Emmanuel.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Audiomachine&ANEW-The Grotto(DJ Anew版).mp3 Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Audiomachine&ANEW-The Grotto(DJ Anew版).mp3 Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/Jennifer Warnes-The Hunter.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/FreshmanSound-Fear.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/FreshmanSound-Fear.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/赵鹏-船歌.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3 Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3 Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/李宗盛-山丘.FLAC Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/邓丽君-南海姑娘.flac Aug 22 13:36:31 volumio1 volumio[1109]: info: Adding Item to queue: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 22 13:36:31 volumio1 volumio[1109]: info: Using cached record of: music-library/USB/900B-7EA1/2024/张韶涵-阿刁(Live).FLAC Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushQueue Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::saveQueue Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::updateTrackBlock Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrackBlock Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPlay Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::play index 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::play index undefined Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::startPlaybackTimer Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::clearAddPlayTracks USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3 Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand stop Aug 22 13:36:31 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:31 volumio1 volumio[1109]: info: Aug 22 13:36:31 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:31 volumio1 volumio[1109]: info: sendMpdCommand stop took 72 milliseconds Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:31 volumio1 volumio[1109]: info: sendMpdCommand stop took 17 milliseconds Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand clear Aug 22 13:36:31 volumio1 volumio[1109]: info: Aug 22 13:36:31 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:31 volumio1 volumio[1109]: info: Aug 22 13:36:31 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:31 volumio1 volumio[1109]: info: Aug 22 13:36:31 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:31 volumio1 volumio[1109]: info: Aug 22 13:36:31 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:31 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:31 volumio1 volumio[1109]: info: sendMpdCommand status took 17 milliseconds Aug 22 13:36:31 volumio1 volumio[1109]: info: sendMpdCommand clear took 17 milliseconds Aug 22 13:36:31 volumio1 volumio[1109]: info: sendMpdCommand status took 14 milliseconds Aug 22 13:36:31 volumio1 volumio[1109]: info: sendMpdCommand status took 12 milliseconds Aug 22 13:36:31 volumio1 volumio[1109]: info: sendMpdCommand status took 10 milliseconds Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand add "USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3" Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:31 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:31 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: No code Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:31 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: No code Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 22 13:36:31 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:31 volumio1 volumio[1109]: info: No code Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:31 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:31 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 222ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 222ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 220ms Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:32 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:32 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:32 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:32 volumio1 volumio[1109]: error: updateQueue error: null Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:32 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 228ms Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 224 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand add "USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3" took 223 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 14ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 12ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 10ms Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand play Aug 22 13:36:32 volumio1 volumio[1109]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 250ms Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:32 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:32 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces system playlist update Aug 22 13:36:32 volumio1 volumio[1109]: info: Ignoring MPD Status Update Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 50ms Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand play took 46 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 44ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 43ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 41ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 24 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 22 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 20 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 14 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 22 13:36:32 volumio1 volumio[1109]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 22 13:36:32 volumio1 volumio[1109]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 90 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 86 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 87 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 87 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 87 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 84 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 82 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus stop Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:32 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":377,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:32 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1108,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:32 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 195ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 288ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 287ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 285ms Aug 22 13:36:32 volumio1 volumio[1109]: info: Aug 22 13:36:32 volumio1 volumio[1109]: ---------------------------- MPD announces state update: player Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::getState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand status Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 178 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 176 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 176 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand status took 6 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseState Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1485,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:32 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1485,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:32 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1485,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:32 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 393ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 380ms Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 379ms Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: info: sendMpdCommand playlistinfo took 167 milliseconds Aug 22 13:36:32 volumio1 volumio[1109]: verbose: ControllerMpd::parseTrackInfo Aug 22 13:36:32 volumio1 volumio[1109]: info: ControllerMpd::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::servicePushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1977,"duration":91,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"The Grotto(纯音乐版)","artist":"柒音","album":"动感旋律节奏","uri":"USB/900B-7EA1/2024/柒音-The Grotto(纯音乐版).mp3","trackType":"mp3"} Aug 22 13:36:32 volumio1 volumio[1109]: verbose: CURRENT POSITION 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState stateService play Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::syncState currentStatus play Aug 22 13:36:32 volumio1 volumio[1109]: info: Received an update from plugin. extracting info from payload Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreStateMachine::pushState Aug 22 13:36:32 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:32 volumio1 volumio[1109]: info: CoreCommandRouter::volumioPushState Aug 22 13:36:32 volumio1 volumio[1109]: info: ------------------------------ 217ms Aug 22 13:36:32 volumio1 volumio[1109]: info: FusionDsp - {"Reload":{"result":"Ok"}} Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:32 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:33 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:33 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:34 volumio1 volumio[1109]: info: Getting Spotify volume Aug 22 13:36:34 volumio1 volumio[1109]: (node:1109) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:34 volumio1 volumio[1109]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 22 13:36:34 volumio1 volumio[1109]: (node:1109) 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) Aug 22 13:36:34 volumio1 volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 22 13:36:34 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:34 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:34 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:34 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:34 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:34 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:34 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Aug 22 13:36:34 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:34 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:34 volumio1 go-librespot[3220]: Librespot-go daemon starting... Aug 22 13:36:34 volumio1 go-librespot[3220]: time="2024-08-22T13:36:34+08:00" level=info msg="generated new device id: 2981f824b1aaed182484a8442deff05ebdce3e70" Aug 22 13:36:34 volumio1 go-librespot[3220]: time="2024-08-22T13:36:34+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:34 volumio1 go-librespot[3220]: time="2024-08-22T13:36:34+08:00" level=debug msg="obtained new client token: AAA5wDA2/n7jRhvVhy+cjn9uQRcDPxa+/zNasi7SBFljQhSr4XADEg9047hNk2Qw0YrvKQi+nCYZzwzB1NE00sniCBDZhwYH3enu7VwTqWNOyy4acPHaolK+LUy+wnEBuXh+6zPIQuHWQoxiPKux5tldeAQO/SyIFeM8vvHEBwxnpRQzUNHdYUJXw13fbQqceVY/AvmN0CEdbawCAg6K0gafVWmrLZvf2QSImuN/o1lBqc4EwnkA6GOfFjW3iA==" Aug 22 13:36:35 volumio1 go-librespot[3220]: time="2024-08-22T13:36:35+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]" Aug 22 13:36:35 volumio1 go-librespot[3220]: time="2024-08-22T13:36:35+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:35 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:35 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:36 volumio1 go-librespot[3220]: time="2024-08-22T13:36:36+08:00" level=debug msg="completed challenge" Aug 22 13:36:36 volumio1 go-librespot[3220]: time="2024-08-22T13:36:36+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:36 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:36 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:37 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:37 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:37 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:37 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:39 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:39 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Aug 22 13:36:39 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:39 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:39 volumio1 go-librespot[3238]: Librespot-go daemon starting... Aug 22 13:36:39 volumio1 go-librespot[3238]: time="2024-08-22T13:36:39+08:00" level=info msg="generated new device id: e379bdddd374d2560f1b2844083c6b34068b539c" Aug 22 13:36:39 volumio1 go-librespot[3238]: time="2024-08-22T13:36:39+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:39 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:39 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:39 volumio1 go-librespot[3238]: time="2024-08-22T13:36:39+08:00" level=debug msg="obtained new client token: AABqxrddMsebLfi7VUi21chd4mNu5KyG8/viccRKKYRPeReZGsAzVb2iQtNAICT2mU//qzqcosGwYE1HVQaOkX+MWuDV3X6mLwt7YmJKG9LW4mTcUi83rPlgmdGn/pzoOqEtPC5GD9775qQ9F4M6JH8sv4hhfITskmkK4vB53CcuwBYiUKegF6YAn9uhVxJ5SJy7HjbtCdWQCjsTFV8M8l+3iShaBqAQphpiE5kr7SjHNb/mk+Eon8QS1yUEcg==" Aug 22 13:36:39 volumio1 go-librespot[3238]: time="2024-08-22T13:36: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]" Aug 22 13:36:40 volumio1 go-librespot[3238]: time="2024-08-22T13:36:40+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:40 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:40 volumio1 go-librespot[3238]: time="2024-08-22T13:36:40+08:00" level=debug msg="new websocket client" Aug 22 13:36:40 volumio1 volumio[1109]: info: Connection to go-librespot Websocket established Aug 22 13:36:40 volumio1 go-librespot[3238]: time="2024-08-22T13:36:40+08:00" level=debug msg="completed challenge" Aug 22 13:36:41 volumio1 go-librespot[3238]: time="2024-08-22T13:36:41+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:41 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:41 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:41 volumio1 volumio[1109]: info: Connection to go-librespot Websocket closed Aug 22 13:36:41 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:41 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:43 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:43 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:43 volumio1 volumio[1109]: info: Getting Spotify volume Aug 22 13:36:43 volumio1 volumio[1109]: (node:1109) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:43 volumio1 volumio[1109]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 22 13:36:43 volumio1 volumio[1109]: (node:1109) 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) Aug 22 13:36:43 volumio1 volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 22 13:36:43 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:43 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:43 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:44 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:44 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:44 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:44 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Aug 22 13:36:44 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:44 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:44 volumio1 go-librespot[3257]: Librespot-go daemon starting... Aug 22 13:36:44 volumio1 go-librespot[3257]: time="2024-08-22T13:36:44+08:00" level=info msg="generated new device id: 41f635155ae7b0f578f54960e8512335c4ada82d" Aug 22 13:36:44 volumio1 go-librespot[3257]: time="2024-08-22T13:36:44+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:44 volumio1 go-librespot[3257]: time="2024-08-22T13:36:44+08:00" level=debug msg="obtained new client token: AAAQrRlqtdY5mwlIG2WNS5qYPycjbfaY96PDXi47VZmOsUDY5UpMTi2DzWilJ+lwcG0tuqtdo0K0K/1vvC6bq/xm6hpkg6/pp3RgqkbHXXC+duMH2mpGIEbMG+u+9sAgZOWUU9liiwybMnx8egiVmbg9kmf/G0yTGO/7eQ2mmKi3hmZlUUy3yLMhdWN4YVNvmc4w2NgiyfyxynWdkKzM9wBofxENUtC/WwFS9QlT+WOqx3N7QB4mrdiGSA5+OA==" Aug 22 13:36:45 volumio1 go-librespot[3257]: time="2024-08-22T13:36:45+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]" Aug 22 13:36:45 volumio1 go-librespot[3257]: time="2024-08-22T13:36:45+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:45 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:45 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:45 volumio1 go-librespot[3257]: time="2024-08-22T13:36:45+08:00" level=debug msg="completed challenge" Aug 22 13:36:45 volumio1 go-librespot[3257]: time="2024-08-22T13:36:45+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:45 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:45 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:47 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:47 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:47 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:47 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:48 volumio1 volumio[1109]: error: MyVolumio got a network error: A network error (such as timeout, interrupted connection or unreachable host) has occurred. Aug 22 13:36:48 volumio1 volumio[1109]: info: Retrying Login Due to Network Error Aug 22 13:36:48 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:48 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Aug 22 13:36:48 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:48 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:48 volumio1 go-librespot[3273]: Librespot-go daemon starting... Aug 22 13:36:48 volumio1 go-librespot[3273]: time="2024-08-22T13:36:48+08:00" level=info msg="generated new device id: bde7e08dec8b74572c2e566bf52f3bd14c7b10c8" Aug 22 13:36:48 volumio1 go-librespot[3273]: time="2024-08-22T13:36:48+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:49 volumio1 go-librespot[3273]: time="2024-08-22T13:36:49+08:00" level=debug msg="obtained new client token: AADkd9YUzy1ykagNcr9fPdJVS4SqaWCygHlWHhU2CJQ/qU30Z7d+8eLhUrT5ETjfMbgE4p6pDgHONm0o/pULAqVyCY6+AqLlbcjPRc0sVuIh/Nmdw1LAKrahOWHZzZEVUkHJM3syLV8/7Bkn5t5KsA/AAAsoxEuoaRdoROrFCCsmHcbKdrP/rUQ2PXJxGGwwBvMZJOgpOyafVrvOgjyh++cza+eVFMggTQ3tq6NYfDHj0PPbDTT2hi5XkwM=" Aug 22 13:36:49 volumio1 go-librespot[3273]: time="2024-08-22T13:36: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 22 13:36:49 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:49 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:49 volumio1 go-librespot[3273]: time="2024-08-22T13:36:49+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:50 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:50 volumio1 go-librespot[3273]: time="2024-08-22T13:36:50+08:00" level=debug msg="new websocket client" Aug 22 13:36:50 volumio1 volumio[1109]: info: Connection to go-librespot Websocket established Aug 22 13:36:50 volumio1 go-librespot[3273]: time="2024-08-22T13:36:50+08:00" level=debug msg="completed challenge" Aug 22 13:36:50 volumio1 go-librespot[3273]: time="2024-08-22T13:36:50+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:50 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:50 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:50 volumio1 volumio[1109]: info: Connection to go-librespot Websocket closed Aug 22 13:36:51 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:51 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:53 volumio1 volumio[1109]: info: Getting Spotify volume Aug 22 13:36:53 volumio1 volumio[1109]: (node:1109) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:53 volumio1 volumio[1109]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) Aug 22 13:36:53 volumio1 volumio[1109]: (node:1109) 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: 42) Aug 22 13:36:53 volumio1 volumio[1109]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 22 13:36:53 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:53 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:53 volumio1 volumio[1109]: SPOTIFY: RECEIVED VOLUMIO VOLUME 56 Aug 22 13:36:53 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:53 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:53 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:53 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Aug 22 13:36:53 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:53 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:53 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:53 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:53 volumio1 go-librespot[3291]: Librespot-go daemon starting... Aug 22 13:36:53 volumio1 go-librespot[3291]: time="2024-08-22T13:36:53+08:00" level=info msg="generated new device id: 3956853ce5fba744ff243bb69cc24c8f2843bb0b" Aug 22 13:36:53 volumio1 go-librespot[3291]: time="2024-08-22T13:36:53+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:54 volumio1 go-librespot[3291]: time="2024-08-22T13:36:54+08:00" level=debug msg="obtained new client token: AAA/LWlPs2mxX0Lsd9etn8rTsQF0lHMO5ZFE3UPCpYTWtrlgEyFM3naoigmEzWnMng4oflZ6U2tMrM5kFJUI4P2lV89ItiXhWb68QemiTLOT8g+iqYY+h/4S5Rn4x0/DzkJLyRj6MReBQXitxIZ04B0G+V0PCHSxfsXgVJiAZXOpAsTJ1GJ8gEv9J4Hb0xgO/pk3KUR941riwBTDaWINcPYGTxcCUO+ZtkGkMqjDVkIfLi+ckWdPyUt0I08=" Aug 22 13:36:54 volumio1 go-librespot[3291]: time="2024-08-22T13:36:54+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 22 13:36:54 volumio1 go-librespot[3291]: time="2024-08-22T13:36:54+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:54 volumio1 go-librespot[3291]: time="2024-08-22T13:36:54+08:00" level=debug msg="completed challenge" Aug 22 13:36:55 volumio1 go-librespot[3291]: time="2024-08-22T13:36:55+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:55 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:55 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:36:55 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:55 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:56 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:56 volumio1 volumio[1109]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 22 13:36:57 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:57 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:58 volumio1 volumio[1109]: info: MyVolumio login type: Token Aug 22 13:36:58 volumio1 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 22 13:36:58 volumio1 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 105. Aug 22 13:36:58 volumio1 systemd[1]: Stopped go-librespot Daemon. Aug 22 13:36:58 volumio1 systemd[1]: Started go-librespot Daemon. Aug 22 13:36:58 volumio1 go-librespot[3307]: Librespot-go daemon starting... Aug 22 13:36:58 volumio1 go-librespot[3307]: time="2024-08-22T13:36:58+08:00" level=info msg="generated new device id: cb415f7d8048da01143d17edf710c324381a496a" Aug 22 13:36:58 volumio1 go-librespot[3307]: time="2024-08-22T13:36:58+08:00" level=debug msg="stored credentials found for 31wzrroqnrbmejauqhehx7fikghu" Aug 22 13:36:58 volumio1 go-librespot[3307]: time="2024-08-22T13:36:58+08:00" level=debug msg="obtained new client token: AADVKh4mwUokkvVdXo9vDy6IyEBT3yY3YXPXSOAz4Z5kktEDPtlfbg6JDzcA74SkB60XJ79uOjMuNqWNyO6zp2EMDr3g496R05xM+ZXBzpgW+/rqqkYpbovQWLs5ul0umT6ujpxfnsuqT0Yd3Bgn9QZO1uBiAX1P1sX4QeC++RvtMCdp6e4vD4gCHFc6TuLya1ekvY4tQfFFkb5BOouGvk3jd0x4+AyyPSaLksyuduI+o673ApBM3XTdb0dDLA==" Aug 22 13:36:58 volumio1 go-librespot[3307]: time="2024-08-22T13:36:58+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]" Aug 22 13:36:59 volumio1 go-librespot[3307]: time="2024-08-22T13:36:59+08:00" level=debug msg="completed keyexchange" Aug 22 13:36:59 volumio1 volumio[1109]: info: Initializing connection to go-librespot Websocket Aug 22 13:36:59 volumio1 go-librespot[3307]: time="2024-08-22T13:36:59+08:00" level=debug msg="new websocket client" Aug 22 13:36:59 volumio1 volumio[1109]: info: Connection to go-librespot Websocket established Aug 22 13:36:59 volumio1 volumio[1109]: info: CoreCommandRouter::volumioGetState Aug 22 13:36:59 volumio1 volumio[1109]: info: CorePlayQueue::getTrack 9 Aug 22 13:36:59 volumio1 go-librespot[3307]: time="2024-08-22T13:36:59+08:00" level=debug msg="completed challenge" Aug 22 13:36:59 volumio1 volumio[1109]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 22 13:36:59 volumio1 volumio[1109]: Error: connect ETIMEDOUT 168.143.171.189:443 Aug 22 13:36:59 volumio1 volumio[1109]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1159:16) { Aug 22 13:36:59 volumio1 volumio[1109]: errno: -110, Aug 22 13:36:59 volumio1 volumio[1109]: code: 'ETIMEDOUT', Aug 22 13:36:59 volumio1 volumio[1109]: syscall: 'connect', Aug 22 13:36:59 volumio1 volumio[1109]: address: '168.143.171.189', Aug 22 13:36:59 volumio1 volumio[1109]: port: 443 Aug 22 13:36:59 volumio1 volumio[1109]: } Aug 22 13:36:59 volumio1 volumio[1109]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 22 13:36:59 volumio1 go-librespot[3307]: time="2024-08-22T13:36:59+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 22 13:36:59 volumio1 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 22 13:36:59 volumio1 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 22 13:37:00 volumio1 sudo[3329]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-22 13:36 Aug 22 13:37:00 volumio1 sudo[3329]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="6e682b9410d28f3874f90b2d7789db824a859264" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="7c81f20187867c3bd55475ead0f12800fe93082c" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat 08 Jun 2024 10:32:20 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="orangepipc" VOLUMIO_DEVICENAME="Orange Pi PC" VOLUMIO_HASH="85fabbf1ff267d6584c35638894541bf"