May 26 20:11:06 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: jellyfin , handleBrowseUri May 26 20:11:06 office volumio[1405]: info: [jellyfin-browse] browseUri: jellyfin May 26 20:11:06 office volumio[1405]: info: Preload queue cleared May 26 20:11:07 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: jellyfin , handleBrowseUri May 26 20:11:07 office volumio[1405]: info: [jellyfin-browse] browseUri: jellyfin/jay@fd651f8007e84338b08af97142ed0b57 May 26 20:11:07 office volumio[1405]: verbose: [jellyfin] getItemsFromAPI(): {"userId":"63a63edd43674f73a8fa0af6d0816c3a","enableImageTypes":["Primary"],"imageTypeLimit":1,"recursive":true,"startIndex":0,"limit":47,"sortBy":["SortName"],"sortOrder":["Ascending"]} May 26 20:11:07 office volumio[1405]: verbose: [jellyfin] getItemsFromAPI(): https://jellyfin.hp.arczius.date/UserViews?userId=63a63edd43674f73a8fa0af6d0816c3a May 26 20:11:07 office volumio[1405]: verbose: [jellyfin] getItemsFromAPI(): {"userId":"63a63edd43674f73a8fa0af6d0816c3a","enableImageTypes":["Primary"],"imageTypeLimit":1,"recursive":true,"parentId":"7e64e319657a9516ec78490da03edccb","startIndex":0,"limit":11,"sortBy":["DateCreated","SortName"],"sortOrder":["Descending","Ascending"],"includeItemTypes":["MusicAlbum"]} May 26 20:11:07 office volumio[1405]: verbose: [jellyfin] getItemsFromAPI(): https://jellyfin.hp.arczius.date/Items?userId=63a63edd43674f73a8fa0af6d0816c3a&startIndex=0&limit=11&recursive=true&sortOrder=Descending&sortOrder=Ascending&parentId=7e64e319657a9516ec78490da03edccb&includeItemTypes=MusicAlbum&sortBy=DateCreated&sortBy=SortName&imageTypeLimit=1&enableImageTypes=Primary May 26 20:11:07 office volumio[1405]: info: Preload queue cleared May 26 20:11:07 office volumio[1405]: info: Preload queue cleared May 26 20:11:09 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: jellyfin , handleBrowseUri May 26 20:11:09 office volumio[1405]: info: [jellyfin-browse] browseUri: jellyfin/jay@fd651f8007e84338b08af97142ed0b57/songs@albumId=8ab56dfa92f326f355fe9c89a46deddf May 26 20:11:09 office volumio[1405]: verbose: [jellyfin] getItemsFromAPI(): {"userId":"63a63edd43674f73a8fa0af6d0816c3a","enableImageTypes":["Primary"],"imageTypeLimit":1,"recursive":true,"parentId":"8ab56dfa92f326f355fe9c89a46deddf","startIndex":0,"sortBy":["SortName"],"sortOrder":["Ascending"],"fields":["MediaSources"],"includeItemTypes":["Audio"]} May 26 20:11:09 office volumio[1405]: verbose: [jellyfin] getItemsFromAPI(): https://jellyfin.hp.arczius.date/Items?userId=63a63edd43674f73a8fa0af6d0816c3a&startIndex=0&recursive=true&sortOrder=Ascending&parentId=8ab56dfa92f326f355fe9c89a46deddf&fields=MediaSources&includeItemTypes=Audio&sortBy=SortName&imageTypeLimit=1&enableImageTypes=Primary May 26 20:11:09 office volumio[1405]: info: Preload queue cleared May 26 20:11:09 office volumio[1405]: info: No valid Plugin REST Endpoint May 26 20:11:09 office volumio[1405]: info: No valid Plugin REST Endpoint May 26 20:11:09 office volumio[1405]: info: No valid Plugin REST Endpoint May 26 20:11:09 office volumio[1405]: info: No valid Plugin REST Endpoint May 26 20:11:10 office volumio[1405]: info: Preload queue cleared May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioReplaceandPlayItems May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::ClearQueue May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::stop May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::setConsumeUpdateService undefined May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::stPlaybackTimer May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::updateTrackBlock May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrackBlock May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::serviceStop May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::serviceStop May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::setConsumeUpdateService mpd May 26 20:11:10 office volumio[1405]: info: ControllerMpd::stop May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand stop May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::clearPlayQueue May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::saveQueue May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushQueue May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::addQueueItems May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::addQueueItems May 26 20:11:10 office volumio[1405]: info: Preload queue cleared May 26 20:11:10 office volumio[1405]: info: Adding Item to queue: jellyfin/jay@fd651f8007e84338b08af97142ed0b57/songs@albumId=8ab56dfa92f326f355fe9c89a46deddf May 26 20:11:10 office volumio[1405]: info: Using cached record of: jellyfin/jay@fd651f8007e84338b08af97142ed0b57/songs@albumId=8ab56dfa92f326f355fe9c89a46deddf May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.159Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_STOPPED positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.160Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=ed0cef4acec9a64471448e801545b601" title="Serve The Servants" May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushQueue May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::saveQueue May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::updateTrackBlock May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrackBlock May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPlay May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::play index 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::setConsumeUpdateService undefined May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::stop May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::setConsumeUpdateService undefined May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::play index undefined May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::setConsumeUpdateService undefined May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::startPlaybackTimer May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: [jellyfin-play] clearAddPlayTrack: jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: sendMpdCommand stop took 26 milliseconds May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 2 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 2 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 10 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 10 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 10 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 6 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 4 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 3 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received mpd May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.206Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_STOPPED positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.207Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio[1405]: info: ------------------------------ 27ms May 26 20:11:10 office volumio[1405]: info: Pushing Favourites {"favourite":false} May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 23 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 23 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 23 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 23 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received mpd May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received mpd May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received mpd May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current jellyfin Received mpd May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.230Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_STOPPED positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.231Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.231Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_STOPPED positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.232Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.233Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_STOPPED positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.233Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_STOPPED positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.233Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.234Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio[1405]: info: ------------------------------ 68ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 67ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 63ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 63ms May 26 20:11:10 office volumio[1405]: info: [jellyfin-play] Stream URL for 4 Raws: https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78 May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand stop May 26 20:11:10 office volumio[1405]: info: [jellyfin-play]: Reported 'stop' for song: Serve The Servants (at 19175 ms) May 26 20:11:10 office volumio[1405]: info: sendMpdCommand stop took 2 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand clear May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: sendMpdCommand clear took 1 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand load "https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac" May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: error: updateQueue error: null May 26 20:11:10 office volumio[1405]: info: ------------------------------ 5ms May 26 20:11:10 office volumio[1405]: error: updateQueue error: null May 26 20:11:10 office volumio[1405]: error: updateQueue error: null May 26 20:11:10 office volumio[1405]: error: updateQueue error: null May 26 20:11:10 office volumio[1405]: error: updateQueue error: null May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand addid "https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac" May 26 20:11:10 office volumio[1405]: info: ------------------------------ 36ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 35ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 34ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 33ms May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: sendMpdCommand addid "https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac" took 2 milliseconds May 26 20:11:10 office volumio[1405]: verbose: MPD COMMAND [object Object] May 26 20:11:10 office volumio[1405]: verbose: MPD COMMAND [object Object] May 26 20:11:10 office volumio[1405]: verbose: MPD COMMAND [object Object] May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: ------------------------------ 6ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 5ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 4ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 3ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 2ms May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::setConsumeUpdateService mpd May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand play May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: ------------------------------ 5ms May 26 20:11:10 office volumio[1405]: info: sendMpdCommand play took 4 milliseconds May 26 20:11:10 office volumio[1405]: info: ------------------------------ 4ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 4ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 3ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 5ms May 26 20:11:10 office volumio[1405]: info: [jellyfin-play]: Mark song 4 Raws as played by jay. May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 11 milliseconds May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 12 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 11 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 10 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 9 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 8 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 14 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 14 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 13 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 19 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 19 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 15 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 14 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 14 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 14 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 14 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 14 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 11 milliseconds May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 11 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 10 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 11 milliseconds May 26 20:11:10 office volumio[1405]: info: ------------------------------ 10ms May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus stop May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ------------------------------ 76ms May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.452Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.453Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.454Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.454Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.455Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.456Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.457Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.458Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.460Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.460Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.462Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.462Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.464Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.464Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.470Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.471Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.474Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.474Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.475Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.476Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.477Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.478Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.480Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=0 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.480Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio[1405]: info: ------------------------------ 150ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 148ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 148ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 147ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 146ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 146ms May 26 20:11:10 office volumio[1405]: info: Pushing Favourites {"favourite":false} May 26 20:11:10 office volumio[1405]: info: Pushing Favourites {"favourite":false} May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces system playlist update May 26 20:11:10 office volumio[1405]: info: Ignoring MPD Status Update May 26 20:11:10 office volumio[1405]: info: May 26 20:11:10 office volumio[1405]: ---------------------------- MPD announces state update: player May 26 20:11:10 office volumio[1405]: info: ControllerMpd::getState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand status May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 153 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 151 milliseconds May 26 20:11:10 office volumio[1405]: info: ------------------------------ 152ms May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 147 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 145 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 144 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 141 milliseconds May 26 20:11:10 office volumio[1405]: info: ------------------------------ 9ms May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 8 milliseconds May 26 20:11:10 office volumio[1405]: info: ------------------------------ 8ms May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 6 milliseconds May 26 20:11:10 office volumio[1405]: info: ------------------------------ 6ms May 26 20:11:10 office volumio[1405]: info: sendMpdCommand status took 6 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseState May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.579Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=158 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.580Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.583Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=158 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.583Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=158 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.585Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=158 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.586Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.586Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.587Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.589Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=158 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.591Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.593Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=158 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.594Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio[1405]: info: ------------------------------ 234ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 234ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 223ms May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 125 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 125 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 124 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 124 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 124 milliseconds May 26 20:11:10 office volumio[1405]: info: sendMpdCommand playlistinfo took 124 milliseconds May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: verbose: ControllerMpd::parseTrackInfo May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":31,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":673,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2652 Kbps","isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":757,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2624 Kbps","isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":757,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2624 Kbps","isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: ControllerMpd::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::servicePushState May 26 20:11:10 office volumio[1405]: info: CorePlayQueue::getTrack 0 May 26 20:11:10 office volumio[1405]: verbose: STATE SERVICE {"status":"play","position":0,"seek":757,"duration":147,"samplerate":"96 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"2624 Kbps","isStreaming":false,"title":"4 Raws","artist":"EsDeeKid","album":"Rebel","uri":"https://jellyfin.hp.arczius.date/Audio/e184f589b17d89d7a32440c7e7f5d79b/stream.flac?static=true&mediaSourceId=e184f589b17d89d7a32440c7e7f5d79b&tag=14434e584ebfb4cc5f31d8016a693f78&t.flac","trackType":"flac"} May 26 20:11:10 office volumio[1405]: verbose: CURRENT POSITION 0 May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState stateService play May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::syncState currentStatus play May 26 20:11:10 office volumio[1405]: info: Received an update from plugin. extracting info from payload May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio[1405]: info: CoreStateMachine::pushState May 26 20:11:10 office volumio[1405]: info: CoreCommandRouter::volumioPushState May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.706Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.706Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.708Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.709Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.709Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.710Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.716Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.716Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.716Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.717Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.720Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.721Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.722Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.723Z level=INFO msg="emitting player state changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" state=STATUS_PLAYING positionMs=287 volume=88 May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.723Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.725Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.725Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.726Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.728Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio5-onboarding[1848]: time=2026-05-26T18:11:10.729Z level=INFO msg="emitting player metadata changed event" component=server peer="192.168.2.2:49732,00:00:00:00:00:00%02 @ 0x1b08900" id="jellyfin/jay@fd651f8007e84338b08af97142ed0b57/song@songId=e184f589b17d89d7a32440c7e7f5d79b" title="4 Raws" May 26 20:11:10 office volumio[1405]: info: ------------------------------ 359ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 358ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 215ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 214ms May 26 20:11:10 office volumio[1405]: info: ------------------------------ 212ms May 26 20:11:10 office volumio[1405]: info: Pushing Favourites {"favourite":false} May 26 20:11:10 office volumio[1405]: info: [jellyfin-play]: Reported 'start' for song: 4 Raws (at 0 ms) May 26 20:11:10 office volumio[1405]: info: [jellyfin-play]: Reported 'timeupdate' for song: 4 Raws (at 0 ms) May 26 20:11:10 office volumio[1405]: info: [jellyfin-play]: Reported 'timeupdate' for song: 4 Raws (at 305 ms) May 26 20:12:05 office volumio5-onboarding[1848]: time=2026-05-26T18:12:05.098Z level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 May 26 20:12:08 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 26 20:12:08 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 26 20:12:13 office volumio5-onboarding[1848]: time=2026-05-26T18:12:13.038Z level=INFO msg="new address was allocated" component=ble/conn old=3 new=4 May 26 20:12:18 office volumio5-onboarding[1848]: time=2026-05-26T18:12:18.688Z level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=2 chunks=1 index=0 tries=11 May 26 20:12:31 office volumio[1405]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf May 26 20:12:31 office volumio5-onboarding[1848]: time=2026-05-26T18:12:31.102Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:33 office volumio[1405]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/spop/volumio/bookworm/armhf May 26 20:12:33 office volumio[1405]: info: Folder /tmp/plugins removed May 26 20:12:33 office volumio5-onboarding[1848]: time=2026-05-26T18:12:33.150Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:33 office volumio5-onboarding[1848]: time=2026-05-26T18:12:33.637Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:33 office volumio[1405]: info: Check plugin dependencies May 26 20:12:33 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 20:12:33 office volumio5-onboarding[1848]: time=2026-05-26T18:12:33.708Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:33 office volumio[1405]: info: Checking if plugin already exists May 26 20:12:33 office volumio5-onboarding[1848]: time=2026-05-26T18:12:33.715Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:33 office volumio[1405]: info: Rename folder May 26 20:12:33 office volumio[1405]: info: Folder /tmp/downloaded_plugin.zip removed May 26 20:12:33 office volumio5-onboarding[1848]: time=2026-05-26T18:12:33.738Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:33 office volumio[1405]: info: Move to category May 26 20:12:34 office volumio5-onboarding[1848]: time=2026-05-26T18:12:34.713Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:34 office volumio[1405]: info: Checking if install.sh is present May 26 20:12:34 office volumio[1405]: info: Executing install.sh May 26 20:12:34 office sudo[3449]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/music_service/spop/install.sh May 26 20:12:34 office sudo[3449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 26 20:12:34 office volumio[1405]: info: Installing Go-librespot May 26 20:12:34 office volumio5-onboarding[1848]: time=2026-05-26T18:12:34.759Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:34 office volumio[1405]: info: Checking old vollibrespot installs May 26 20:12:34 office volumio5-onboarding[1848]: time=2026-05-26T18:12:34.769Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:34 office systemd[1]: Reloading. May 26 20:12:35 office volumio[1405]: info: Downloading daemon May 26 20:12:35 office volumio5-onboarding[1848]: time=2026-05-26T18:12:35.839Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:38 office volumio[1405]: info: Creating directories May 26 20:12:38 office volumio5-onboarding[1848]: time=2026-05-26T18:12:38.366Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:38 office volumio[1405]: info: Creating data directory May 26 20:12:38 office volumio5-onboarding[1848]: time=2026-05-26T18:12:38.373Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:38 office volumio[1405]: info: Creating Start Script May 26 20:12:38 office volumio5-onboarding[1848]: time=2026-05-26T18:12:38.384Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:40 office systemd[1]: Reloading. May 26 20:12:41 office sudo[3449]: pam_unix(sudo:session): session closed for user root May 26 20:12:41 office volumio[1405]: Plugin install end detected on script May 26 20:12:41 office volumio[1405]: info: Install script completed May 26 20:12:41 office volumio5-onboarding[1848]: time=2026-05-26T18:12:41.735Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:41 office volumio[1405]: info: Adding reference to registry May 26 20:12:41 office volumio5-onboarding[1848]: time=2026-05-26T18:12:41.740Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state May 26 20:12:41 office volumio[1405]: info: Done installing plugin. May 26 20:12:41 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 26 20:12:41 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 26 20:12:41 office volumio[1405]: info: Folder /tmp/plugins removed May 26 20:12:41 office volumio[1405]: info: Folder /tmp/downloaded_plugin.zip removed May 26 20:12:41 office volumio[1405]: info: Folder /data/temp removed May 26 20:12:47 office volumio[1405]: info: Enabling plugin spop May 26 20:12:47 office volumio[1405]: info: Loading plugin "spop"... May 26 20:12:48 office volumio[1405]: info: PLUGIN START: spop May 26 20:12:48 office volumio[1405]: info: Creating Spotify config file May 26 20:12:48 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 20:12:48 office volumio[1405]: info: Done. May 26 20:12:48 office volumio[1405]: info: Spotify config file written May 26 20:12:48 office volumio[1405]: info: No need to fix Spotify hosts May 26 20:12:48 office sudo[3520]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 26 20:12:48 office sudo[3520]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 26 20:12:48 office systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 26 20:12:48 office systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 26 20:12:48 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 26 20:12:48 office go-librespot[3522]: go-librespot daemon starting... May 26 20:12:48 office sudo[3520]: pam_unix(sudo:session): session closed for user root May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=info msg="running go-librespot 0.7.1" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=debug msg="no app state found" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=debug msg="stored credentials not found" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=info msg="generated new device id: 54598ef0603121ec6b476b581b56f68b7c3e0e43" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=info msg="zeroconf server listening on port 41107" May 26 20:12:48 office go-librespot[3523]: time="2026-05-26T20:12:48+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" May 26 20:12:48 office volumio[1405]: info: Enabling plugin spop May 26 20:12:48 office volumio[1405]: info: Loading plugin "spop"... May 26 20:12:48 office volumio[1405]: info: PLUGIN START: spop May 26 20:12:48 office volumio[1405]: info: Creating Spotify config file May 26 20:12:48 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 20:12:48 office volumio[1405]: info: Done. May 26 20:12:48 office volumio[1405]: info: Spotify config file written May 26 20:12:48 office volumio[1405]: info: No need to fix Spotify hosts May 26 20:12:48 office sudo[3534]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 26 20:12:48 office sudo[3534]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 26 20:12:48 office systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... May 26 20:12:48 office systemd[1]: go-librespot-daemon.service: Deactivated successfully. May 26 20:12:48 office systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. May 26 20:12:48 office systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. May 26 20:12:48 office go-librespot[3536]: go-librespot daemon starting... May 26 20:12:48 office sudo[3534]: pam_unix(sudo:session): session closed for user root May 26 20:12:48 office go-librespot[3537]: time="2026-05-26T20:12:48+02:00" level=info msg="running go-librespot 0.7.1" May 26 20:12:48 office go-librespot[3537]: time="2026-05-26T20:12:48+02:00" level=debug msg="app state loaded" May 26 20:12:48 office go-librespot[3537]: time="2026-05-26T20:12:48+02:00" level=debug msg="stored credentials not found" May 26 20:12:48 office go-librespot[3537]: time="2026-05-26T20:12:48+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 26 20:12:49 office go-librespot[3537]: time="2026-05-26T20:12:49+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" May 26 20:12:49 office go-librespot[3537]: time="2026-05-26T20:12:49+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 26 20:12:49 office go-librespot[3537]: time="2026-05-26T20:12:49+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 26 20:12:49 office go-librespot[3537]: time="2026-05-26T20:12:49+02:00" level=info msg="zeroconf server listening on port 40133" May 26 20:12:49 office go-librespot[3537]: time="2026-05-26T20:12:49+02:00" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration" May 26 20:12:51 office volumio[1405]: info: go-librespot daemon successfully initialized May 26 20:12:51 office volumio[1405]: info: go-librespot daemon successfully initialized May 26 20:12:53 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 26 20:12:53 office volumio[1405]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 26 20:12:54 office volumio[1405]: info: Initializing connection to go-librespot Websocket May 26 20:12:54 office go-librespot[3537]: time="2026-05-26T20:12:54+02:00" level=debug msg="new websocket client" May 26 20:12:54 office volumio[1405]: info: Connection to go-librespot Websocket established May 26 20:12:54 office volumio[1405]: info: Initializing connection to go-librespot Websocket May 26 20:12:54 office go-librespot[3537]: time="2026-05-26T20:12:54+02:00" level=debug msg="new websocket client" May 26 20:12:54 office volumio[1405]: info: Connection to go-librespot Websocket established May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="obtained new client token: AACcJScKEwUY9rbXPcMb4ShLXry81nJBiEZ1d0xVZ8nLL5LSkW5Hg9GKBd/uqeEvDhQAlq4h1Zds8VF2mwMRgSJCUk2FYuhJrAv0SphHo9sv9qmBNjZ6o8fQ0kj2F/E+DInsaUeQwWbRQrlrg19hsDOndwnP0VEmgzRg1TEyM+IQXLzaodXj3rEbMFHUtNypVSX6Y1LnQt/cCeVW/OMlhwfYA3YDJ8F3GLVQL/C3OmLKLCf3TJpz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="completed keyexchange" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="completed challenge" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=info msg="authenticated AP" username="31************************bu" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=info msg="authenticated Login5" username="31************************bu" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=info msg="accepted zeroconf from PEAK" username="31************************bu" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="dealer connection opened" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="starting accesspoint recv loop" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="starting dealer recv loop" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="received accesspoint ping" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="received connection id: MjI5YzVmOTQtNmE5...M0MxMERCN0Q2NQ==" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="received accesspoint pong ack" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="put connect state because NEW_DEVICE" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="handling transfer player command from c59d7465b8b37b310abbd2b9960852fd27ed55ab" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1CKMFBxUbxRIAg" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="fetched new page 0 with 91 items (list: 91)" uri="spotify:playlist:37i9dQZF1CKMFBxUbxRIAg" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="loading track (paused: false, position: 373824ms)" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="emitting websocket event: will_play" May 26 20:12:56 office volumio[1405]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1CKMFBxUbxRIAg","uri":"spotify:track:3UmaczJpikHgJFyBTAJVoz","play_origin":"playlist"}} May 26 20:12:56 office volumio[1405]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1CKMFBxUbxRIAg","uri":"spotify:track:3UmaczJpikHgJFyBTAJVoz","play_origin":"playlist"}} May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="selected format OGG_VORBIS_320 (4858f853a0f4fe948a976d637798f50dfd99ff67)" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="requested aes key for file 4858f853a0f4fe948a976d637798f50dfd99ff67, gid: 3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1832" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched first chunk of 38, total size is 19471064 bytes" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched chunk 2/37, size: 524288" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched chunk 37/37, size: 72408" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched chunk 34/37, size: 524288" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="seek to 373824ms (diff: 41ms, samples: 16485638, bytes: 18148490)" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="created new output device" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched chunk 1/37, size: 524288" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=info msg="loaded track \"Stan\" (paused: false, position: 373824ms, duration: 404106ms, prefetched: false)" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched chunk 35/37, size: 524288" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched chunk 36/37, size: 524288" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="fetched chunk 3/37, size: 524288" uri="spotify:track:3UmaczJpikHgJFyBTAJVoz" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="prefetch as soon as possible" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="emitting websocket event: metadata" May 26 20:12:56 office volumio[1405]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3UmaczJpikHgJFyBTAJVoz","name":"Stan","artist_names":["Eminem","Dido"],"album_name":"The Marshall Mathers LP","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02dbb3dd82da45b7d7f31b1b42","position":373824,"duration":404106,"release_date":"year:2000 month:5 day:23","track_number":3,"disc_number":1}} May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="emitting websocket event: active" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="sending successful reply for dealer request" May 26 20:12:56 office volumio[1405]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3UmaczJpikHgJFyBTAJVoz","name":"Stan","artist_names":["Eminem","Dido"],"album_name":"The Marshall Mathers LP","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02dbb3dd82da45b7d7f31b1b42","position":373824,"duration":404106,"release_date":"year:2000 month:5 day:23","track_number":3,"disc_number":1}} May 26 20:12:56 office volumio[1405]: SPOTIFY: received: {"type":"active","data":null} May 26 20:12:56 office volumio[1405]: info: Aligning Spotify Volume to Volumio Volume May 26 20:12:56 office volumio[1405]: info: CoreCommandRouter::volumioGetState May 26 20:12:56 office volumio[1405]: info: Setting Spotify Volume from Volumio: 88 May 26 20:12:56 office volumio[1405]: SPOTIFY: received: {"type":"active","data":null} May 26 20:12:56 office volumio[1405]: info: Aligning Spotify Volume to Volumio Volume May 26 20:12:56 office volumio[1405]: info: CoreCommandRouter::volumioGetState May 26 20:12:56 office volumio[1405]: info: Setting Spotify Volume from Volumio: 88 May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=trace msg="emitting websocket event: playing" May 26 20:12:56 office go-librespot[3537]: time="2026-05-26T20:12:56+02:00" level=debug msg="prefetching next track" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:56 office volumio[1405]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:playlist:37i9dQZF1CKMFBxUbxRIAg","uri":"spotify:track:3UmaczJpikHgJFyBTAJVoz","resume":false,"play_origin":"playlist"}} May 26 20:12:56 office volumio[1405]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 20:12:56 office volumio[1405]: TypeError: Cannot read properties of undefined (reading 'service') May 26 20:12:56 office volumio[1405]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) May 26 20:12:56 office volumio[1405]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) May 26 20:12:56 office volumio[1405]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) May 26 20:12:56 office volumio[1405]: at WebSocket.emit (node:events:514:28) May 26 20:12:56 office volumio[1405]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 26 20:12:56 office volumio[1405]: at Receiver.emit (node:events:514:28) May 26 20:12:56 office volumio[1405]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 26 20:12:56 office volumio[1405]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 26 20:12:56 office volumio[1405]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 26 20:12:56 office volumio[1405]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 26 20:12:56 office volumio[1405]: at writeOrBuffer (node:internal/streams/writable:399:12) May 26 20:12:56 office volumio[1405]: at _write (node:internal/streams/writable:340:10) May 26 20:12:56 office volumio[1405]: at Writable.write (node:internal/streams/writable:344:10) May 26 20:12:56 office volumio[1405]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 26 20:12:56 office volumio[1405]: at Socket.emit (node:events:514:28) May 26 20:12:56 office volumio[1405]: at addChunk (node:internal/streams/readable:343:12) May 26 20:12:57 office volumio[1405]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=debug msg="selected format OGG_VORBIS_320 (9fd315929ba7ae31d69c0b8c9fd8a64e595f315e)" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=debug msg="requested aes key for file 9fd315929ba7ae31d69c0b8c9fd8a64e595f315e, gid: 48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=debug msg="fetched first chunk of 27, total size is 13848288 bytes" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=info msg="prefetched track \"Californication\" (duration: 329733ms)" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=debug msg="fetched chunk 1/26, size: 524288" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=debug msg="fetched chunk 3/26, size: 524288" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office go-librespot[3537]: time="2026-05-26T20:12:57+02:00" level=debug msg="fetched chunk 2/26, size: 524288" uri="spotify:track:48UPSzbZjgc449aqz8bxox" May 26 20:12:57 office sudo[3577]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-26 20:11' May 26 20:12:57 office sudo[3577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"