-- Logs begin at Wed 2024-09-04 11:44:34 CDT, end at Thu 2024-09-05 19:11:14 CDT. -- Sep 05 19:10:02 volumio1 go-librespot[1293]: time="2024-09-05T19:10:02-05:00" level=debug msg="renewing login5 access token" Sep 05 19:10:05 volumio1 volumio[846]: info: Preload queue cleared Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioReplaceandPlayItems Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::ClearQueue Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::stop Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::stPlaybackTimer Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::updateTrackBlock Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrackBlock Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 5 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::serviceStop Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 5 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::serviceStop Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::stop Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::clearPlayQueue Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::saveQueue Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushQueue Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::addQueueItems Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::addQueueItems Sep 05 19:10:05 volumio1 volumio[846]: info: Preload queue cleared Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Twist And Shout.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Twist And Shout.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-That Lady (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-That Lady (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-What It Comes Down To.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-What It Comes Down To.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Brown Eyed Girl.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Brown Eyed Girl.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-For The Love Of You (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-For The Love Of You (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Groove With You.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Groove With You.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Brother Brother.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Brother Brother.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Work To Do.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Work To Do.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Summer Breeze.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Summer Breeze.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Make Me Say It Again Girl (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Make Me Say It Again Girl (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Live It Up (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Live It Up (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Fight The Power (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Fight The Power (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Freedom.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Freedom.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Keep On Doin'.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Keep On Doin'.MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-This Old Heart Of Mine (Is Weak For You).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-This Old Heart Of Mine (Is Weak For You).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Move Over And Let Me Dance (With Jimi Hendrix).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Move Over And Let Me Dance (With Jimi Hendrix).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Adding Item to queue: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Shout (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: Using cached record of: music-library/USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Shout (Parts 1 And 2).MP3 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushQueue Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::saveQueue Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::updateTrackBlock Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrackBlock Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPlay Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::play index 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::stop Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::play index undefined Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::startPlaybackTimer Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::clearAddPlayTracks USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3 Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand stop Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand stop took 98 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand stop took 28 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand clear Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces system playlist update Sep 05 19:10:05 volumio1 volumio[846]: info: Ignoring MPD Status Update Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 22 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand clear took 21 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 19 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 17 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand add "USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3" Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService stop Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus stop Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: No code Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService stop Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus stop Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: No code Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 99ms Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 99ms Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces system playlist update Sep 05 19:10:05 volumio1 volumio[846]: info: Ignoring MPD Status Update Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces system playlist update Sep 05 19:10:05 volumio1 volumio[846]: info: Ignoring MPD Status Update Sep 05 19:10:05 volumio1 volumio[846]: error: updateQueue error: null Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces system playlist update Sep 05 19:10:05 volumio1 volumio[846]: info: Ignoring MPD Status Update Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 99ms Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand playlistinfo took 91 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand add "USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3" took 91 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 14ms Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 12ms Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseTrackInfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand play Sep 05 19:10:05 volumio1 volumio[846]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 134ms Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces system playlist update Sep 05 19:10:05 volumio1 volumio[846]: info: Ignoring MPD Status Update Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces system playlist update Sep 05 19:10:05 volumio1 volumio[846]: info: Ignoring MPD Status Update Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 44ms Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand play took 35 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 31ms Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 31ms Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 15 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 16 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 10 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 7 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: info: Sep 05 19:10:05 volumio1 volumio[846]: ---------------------------- MPD announces state update: player Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::getState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand status Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand playlistinfo took 44 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand playlistinfo took 43 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand playlistinfo took 40 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand playlistinfo took 40 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 36 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand status took 33 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseTrackInfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseTrackInfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseTrackInfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseTrackInfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseState Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":234,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Harvest For The World","artist":"Isley Brothers","album":"Essential Disc 1","uri":"USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3","trackType":"MP3"} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService play Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus stop Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":234,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Harvest For The World","artist":"Isley Brothers","album":"Essential Disc 1","uri":"USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3","trackType":"MP3"} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService play Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus play Sep 05 19:10:05 volumio1 volumio[846]: info: Received an update from plugin. extracting info from payload Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":234,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Harvest For The World","artist":"Isley Brothers","album":"Essential Disc 1","uri":"USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3","trackType":"MP3"} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService play Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus play Sep 05 19:10:05 volumio1 volumio[846]: info: Received an update from plugin. extracting info from payload Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":234,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Harvest For The World","artist":"Isley Brothers","album":"Essential Disc 1","uri":"USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3","trackType":"MP3"} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService play Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus play Sep 05 19:10:05 volumio1 volumio[846]: info: Received an update from plugin. extracting info from payload Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 132ms Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 152ms Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 145ms Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 143ms Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand playlistinfo took 86 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: info: sendMpdCommand playlistinfo took 86 milliseconds Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseTrackInfo Sep 05 19:10:05 volumio1 volumio[846]: verbose: ControllerMpd::parseTrackInfo Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":234,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Harvest For The World","artist":"Isley Brothers","album":"Essential Disc 1","uri":"USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3","trackType":"MP3"} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService play Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus play Sep 05 19:10:05 volumio1 volumio[846]: info: Received an update from plugin. extracting info from payload Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: ControllerMpd::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::servicePushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":234,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Harvest For The World","artist":"Isley Brothers","album":"Essential Disc 1","uri":"USB/B802EEB702EE79B0/Isley Brothers-Essential Disc 1-Harvest For The World.MP3","trackType":"MP3"} Sep 05 19:10:05 volumio1 volumio[846]: verbose: CURRENT POSITION 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState stateService play Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::syncState currentStatus play Sep 05 19:10:05 volumio1 volumio[846]: info: Received an update from plugin. extracting info from payload Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: CoreStateMachine::pushState Sep 05 19:10:05 volumio1 volumio[846]: info: CorePlayQueue::getTrack 8 Sep 05 19:10:05 volumio1 volumio[846]: info: CoreCommandRouter::volumioPushState Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 179ms Sep 05 19:10:05 volumio1 volumio[846]: info: ------------------------------ 178ms Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:05 volumio1 volumio[846]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Sep 05 19:10:07 volumio1 volumio[846]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/fa-tags.svg' Sep 05 19:10:07 volumio1 go-librespot[1293]: time="2024-09-05T19:10:07-05:00" level=error msg="did not receive last pong ack from accesspoint, 205s passed" Sep 05 19:10:08 volumio1 go-librespot[1293]: time="2024-09-05T19:10:08-05:00" level=error msg="did not receive last pong from dealer, 360s passed" Sep 05 19:10:32 volumio1 volumio[846]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/fa-tags.svg' Sep 05 19:10:36 volumio1 volumio[846]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/fa-tags.svg' Sep 05 19:10:38 volumio1 go-librespot[1293]: time="2024-09-05T19:10:38-05:00" level=error msg="did not receive last pong from dealer, 390s passed" Sep 05 19:10:44 volumio1 go-librespot[1293]: time="2024-09-05T19:10:44-05:00" level=warning msg="failed fetching new endpoint for accesspoint" error="failed fetching apresolve URL: Get \"https://apresolve.spotify.com/?type=accesspoint\": dial tcp: lookup apresolve.spotify.com: i/o timeout" Sep 05 19:10:50 volumio1 go-librespot[1293]: time="2024-09-05T19:10:50-05:00" level=debug msg="renewing login5 access token" Sep 05 19:10:55 volumio1 go-librespot[1293]: time="2024-09-05T19:10:55-05:00" level=debug msg="completed keyexchange" Sep 05 19:10:56 volumio1 go-librespot[1293]: time="2024-09-05T19:10:56-05:00" level=debug msg="completed challenge" Sep 05 19:10:58 volumio1 go-librespot[1293]: time="2024-09-05T19:10:58-05:00" level=debug msg="authenticated as tralfaz5" Sep 05 19:10:58 volumio1 go-librespot[1293]: time="2024-09-05T19:10:58-05:00" level=debug msg="re-established accesspoint connection" Sep 05 19:10:58 volumio1 go-librespot[1293]: time="2024-09-05T19:10:58-05:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 05 19:10:58 volumio1 go-librespot[1293]: time="2024-09-05T19:10:58-05:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 05 19:11:04 volumio1 volumio[846]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/volumio/app/plugins/miscellanea/albumart/icons/fa-tags.svg' Sep 05 19:11:08 volumio1 go-librespot[1293]: time="2024-09-05T19:11:08-05:00" level=error msg="did not receive last pong from dealer, 420s passed" Sep 05 19:11:13 volumio1 volumio[846]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 05 19:11:13 volumio1 volumio[846]: Error: connect ETIMEDOUT 151.101.162.79:443 Sep 05 19:11:13 volumio1 volumio[846]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) { Sep 05 19:11:13 volumio1 volumio[846]: errno: -110, Sep 05 19:11:13 volumio1 volumio[846]: code: 'ETIMEDOUT', Sep 05 19:11:13 volumio1 volumio[846]: syscall: 'connect', Sep 05 19:11:13 volumio1 volumio[846]: address: '151.101.162.79', Sep 05 19:11:13 volumio1 volumio[846]: port: 443 Sep 05 19:11:13 volumio1 volumio[846]: } Sep 05 19:11:13 volumio1 volumio[846]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 05 19:11:13 volumio1 go-librespot[1293]: time="2024-09-05T19:11:13-05:00" level=debug msg="authenticated as tralfaz5" Sep 05 19:11:14 volumio1 sudo[2349]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-05 19:10 Sep 05 19:11:14 volumio1 sudo[2349]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"