Aug 31 08:55:05 volumio2139 volumio[1162]: info: [jellyfin-poller] Polled p456ad.asuscomm.com:8096: offline Aug 31 08:55:33 volumio2139 ntpd[1100]: PROTO: 121.174.142.82 unlink local addr 192.168.0.54 -> Aug 31 08:55:35 volumio2139 volumio[1162]: info: [jellyfin-poller] Polled p456ad.asuscomm.com:8096: offline Aug 31 08:55:37 volumio2139 ntpd[1100]: PROTO: 158.247.202.103 unlink local addr 192.168.0.54 -> Aug 31 08:55:38 volumio2139 systemd[1]: Starting systemd-tmpfiles-clean.service - Cleanup of Temporary Directories... Aug 31 08:55:38 volumio2139 systemd[1]: systemd-tmpfiles-clean.service: Deactivated successfully. Aug 31 08:55:38 volumio2139 systemd[1]: Finished systemd-tmpfiles-clean.service - Cleanup of Temporary Directories. Aug 31 08:55:38 volumio2139 systemd[1]: run-credentials-systemd\x2dtmpfiles\x2dclean.service.mount: Deactivated successfully. Aug 31 08:56:05 volumio2139 volumio[1162]: info: [jellyfin-poller] Polled p456ad.asuscomm.com:8096: offline Aug 31 08:56:35 volumio2139 volumio[1162]: info: [jellyfin-poller] Polled p456ad.asuscomm.com:8096: offline Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.148+09:00 level=INFO msg="check connectivity" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.283+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://radio-directory.firebaseapp.com duration=133.878558ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.473+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://www.googleapis.com duration=322.262025ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.513+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://oauth-performer.dfs.volumio.org duration=362.384812ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.548+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://securetoken.googleapis.com duration=397.012959ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.624+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://browsing-performer.dfs.volumio.org duration=473.688537ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.650+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://google.com duration=500.499712ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.699+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://myvolumio.firebaseio.com duration=549.65808ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.738+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=http://pushupdates.volumio.org duration=587.829633ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.894+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://functions.volumio.cloud duration=742.161815ms Aug 31 08:56:38 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:38.896+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://functions.volumio.cloud duration=746.12472ms Aug 31 08:56:38 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:38 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 31 08:56:38 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPlay Aug 31 08:56:38 volumio2139 volumio[1162]: info: CoreStateMachine::play index undefined Aug 31 08:56:38 volumio2139 volumio[1162]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 08:56:38 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 0 Aug 31 08:56:38 volumio2139 volumio[1162]: info: CoreStateMachine::startPlaybackTimer Aug 31 08:56:38 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 0 Aug 31 08:56:38 volumio2139 volumio[1162]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 31 08:56:38 volumio2139 volumio[1162]: info: ControllerMpd::resume Aug 31 08:56:38 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand play Aug 31 08:56:39 volumio2139 volumio[1162]: info: Aug 31 08:56:39 volumio2139 volumio[1162]: ---------------------------- MPD announces state update: player Aug 31 08:56:39 volumio2139 volumio[1162]: info: sendMpdCommand play took 18 milliseconds Aug 31 08:56:39 volumio2139 volumio[1162]: info: ControllerMpd::getState Aug 31 08:56:39 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand status Aug 31 08:56:39 volumio2139 volumio[1162]: info: sendMpdCommand status took 1 milliseconds Aug 31 08:56:39 volumio2139 volumio[1162]: verbose: ControllerMpd::parseState Aug 31 08:56:39 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 08:56:39 volumio2139 volumio[1162]: info: sendMpdCommand playlistinfo took 2 milliseconds Aug 31 08:56:39 volumio2139 volumio[1162]: verbose: ControllerMpd::parseTrackInfo Aug 31 08:56:39 volumio2139 volumio[1162]: info: ControllerMpd::pushState Aug 31 08:56:39 volumio2139 volumio[1162]: info: CoreCommandRouter::servicePushState Aug 31 08:56:39 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 0 Aug 31 08:56:39 volumio2139 volumio[1162]: verbose: STATE SERVICE {"status":"play","position":0,"seek":84734,"duration":445,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1374 Kbps","isStreaming":false,"title":"01 Carta de Amor","artist":"Magico","album":"Carta de Amor-F24-48","uri":"http://p456ad.asuscomm.com:8096/Audio/d987737a182dfe4a8b681a9f66c73f80/stream.flac?static=true&mediaSourceId=d987737a182dfe4a8b681a9f66c73f80&tag=15a167e477d536f3d2f34801ff0dfa5a&t.flac","trackType":"flac"} Aug 31 08:56:39 volumio2139 volumio[1162]: verbose: CURRENT POSITION 0 Aug 31 08:56:39 volumio2139 volumio[1162]: info: CoreStateMachine::syncState stateService play Aug 31 08:56:39 volumio2139 volumio[1162]: info: CoreStateMachine::syncState currentStatus pause Aug 31 08:56:39 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:39 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:39 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:39 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:39 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:39 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:39 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:39.050+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=82725 volume= Aug 31 08:56:39 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:39.050+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:39 volumio2139 volumio[1162]: info: ------------------------------ 46ms Aug 31 08:56:39 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:39.245+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=http://plugins.volumio.org duration=1.093392337s Aug 31 08:56:39 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:39.712+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=https://database.volumio.cloud duration=1.560380227s Aug 31 08:56:39 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:39.967+09:00 level=INFO msg="endpoint is reachable" component=server type=REQUEST_TYPE_CHECK_INTERNET_CONNECTIVITY peer="192.168.0.31:47962 @ 0xc000281800" latency=546.602342ms timeout=10s endpoint=http://cddb.volumio.org duration=1.817470777s Aug 31 08:56:43 volumio2139 volumio[1162]: info: VolumeController::SetAlsaVolume40 Aug 31 08:56:43 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:43 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:43 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:43 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:43 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:43 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:43 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:43.754+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=87241 volume=40 Aug 31 08:56:43 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:43.755+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:44 volumio2139 volumio[1162]: info: VolumeController::SetAlsaVolume39 Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:44 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:44 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:44 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:44.335+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=87998 volume=39 Aug 31 08:56:44 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:44.336+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:44 volumio2139 volumio[1162]: info: VolumeController::SetAlsaVolume33 Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:44 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:44 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:44 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:44 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:44.460+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=87998 volume=33 Aug 31 08:56:44 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:44.460+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:45 volumio2139 volumio[1162]: info: VolumeController::SetAlsaVolume40 Aug 31 08:56:45 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:45 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:45 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:45 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:45 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:45 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:45 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:45.425+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=89001 volume=40 Aug 31 08:56:45 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:45.425+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:46 volumio2139 volumio[1162]: info: VolumeController::SetAlsaVolume42 Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:46 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:46 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:46 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:46.730+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=90251 volume=42 Aug 31 08:56:46 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:46.731+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:46 volumio2139 volumio[1162]: info: VolumeController::SetAlsaVolume50 Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:46 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:46 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:46 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:46 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:46.899+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=90502 volume=50 Aug 31 08:56:46 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:46.899+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioNext Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::next Aug 31 08:56:51 volumio2139 volumio[1162]: info: ControllerMpd::next Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand next Aug 31 08:56:51 volumio2139 volumio[1162]: info: Aug 31 08:56:51 volumio2139 volumio[1162]: ---------------------------- MPD announces state update: player Aug 31 08:56:51 volumio2139 volumio[1162]: info: sendMpdCommand next took 6 milliseconds Aug 31 08:56:51 volumio2139 volumio[1162]: info: ControllerMpd::getState Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand status Aug 31 08:56:51 volumio2139 volumio[1162]: info: sendMpdCommand status took 1 milliseconds Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: ControllerMpd::parseState Aug 31 08:56:51 volumio2139 volumio[1162]: info: ControllerMpd::pushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::servicePushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:51 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 0 Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: CURRENT POSITION 0 Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::syncState stateService stop Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::syncState currentStatus play Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::play index undefined Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 1 Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:51 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 1 Aug 31 08:56:51 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:51.230+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_PLAYING positionMs=94764 volume=50 Aug 31 08:56:51 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:51.231+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=d987737a182dfe4a8b681a9f66c73f80" title="01 Carta de Amor" Aug 31 08:56:51 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:51.232+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_STOPPED positionMs= volume=50 Aug 31 08:56:51 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:51.232+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=4d4ec5e51954a83be4a1698b3ba8b58f" title="02 Magico" Aug 31 08:56:51 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 1 Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::startPlaybackTimer Aug 31 08:56:51 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 1 Aug 31 08:56:51 volumio2139 volumio[1162]: info: [jellyfin-play] clearAddPlayTrack: jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=4d4ec5e51954a83be4a1698b3ba8b58f Aug 31 08:56:51 volumio2139 volumio[1162]: info: ------------------------------ 36ms Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreStateMachine::pushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 1 Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioPushState Aug 31 08:56:51 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output update for this device Aug 31 08:56:51 volumio2139 volumio[1162]: info: MRS: Pushing multiroomSync output Aug 31 08:56:51 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioGetState Aug 31 08:56:51 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 1 Aug 31 08:56:51 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:51.258+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" state=STATUS_STOPPED positionMs=0 volume=50 Aug 31 08:56:51 volumio2139 volumio5-onboarding[1708]: time=2026-08-31T08:56:51.258+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.31:47962 @ 0xc000281800" id="jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=4d4ec5e51954a83be4a1698b3ba8b58f" title="02 Magico" Aug 31 08:56:51 volumio2139 volumio[1162]: info: [jellyfin-play] Stream URL for 02 Magico: http://p456ad.asuscomm.com:8096/Audio/4d4ec5e51954a83be4a1698b3ba8b58f/stream.flac?static=true&mediaSourceId=4d4ec5e51954a83be4a1698b3ba8b58f&tag=2877e3de6e9d043a36b0cc95e111c95f Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 08:56:51 volumio2139 volumio[1162]: info: sendMpdCommand stop took 0 milliseconds Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand clear Aug 31 08:56:51 volumio2139 volumio[1162]: info: Aug 31 08:56:51 volumio2139 volumio[1162]: ---------------------------- MPD announces system playlist update Aug 31 08:56:51 volumio2139 volumio[1162]: info: Ignoring MPD Status Update Aug 31 08:56:51 volumio2139 volumio[1162]: info: sendMpdCommand clear took 1 milliseconds Aug 31 08:56:51 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand load "http://p456ad.asuscomm.com:8096/Audio/4d4ec5e51954a83be4a1698b3ba8b58f/stream.flac?static=true&mediaSourceId=4d4ec5e51954a83be4a1698b3ba8b58f&tag=2877e3de6e9d043a36b0cc95e111c95f&t.flac" Aug 31 08:56:51 volumio2139 volumio[1162]: error: updateQueue error: null Aug 31 08:56:51 volumio2139 volumio[1162]: info: ------------------------------ 1ms Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreCommandRouter::volumioNext Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreStateMachine::next Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreStateMachine::stop Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreStateMachine::play index undefined Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 08:56:52 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 2 Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreStateMachine::startPlaybackTimer Aug 31 08:56:52 volumio2139 volumio[1162]: info: CorePlayQueue::getTrack 2 Aug 31 08:56:52 volumio2139 volumio[1162]: info: [jellyfin-play] clearAddPlayTrack: jellyfin/P456ad@b69f90bbb9ea49ba8b6f85e2cca331b0/song@songId=268154c1de3727bf2649c53e71f803e1 Aug 31 08:56:52 volumio2139 volumio[1162]: info: CoreStateMachine::updateTrackBlock Aug 31 08:56:52 volumio2139 volumio[1162]: info: CorePlayQueue::getTrackBlock Aug 31 08:56:53 volumio2139 volumio[1162]: info: [jellyfin-play] Stream URL for 02 My Song: http://p456ad.asuscomm.com:8096/Audio/268154c1de3727bf2649c53e71f803e1/stream.flac?static=true&mediaSourceId=268154c1de3727bf2649c53e71f803e1&tag=60918fe8e2d65bc5193f8c73f5283187 Aug 31 08:56:53 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 08:56:56 volumio2139 volumio[1162]: info: Executing endpoint metavolumio Aug 31 08:56:56 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 08:56:56 volumio2139 volumio[1162]: info: Executing endpoint metavolumio Aug 31 08:56:56 volumio2139 volumio[1162]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 08:56:59 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand addid "http://p456ad.asuscomm.com:8096/Audio/4d4ec5e51954a83be4a1698b3ba8b58f/stream.flac?static=true&mediaSourceId=4d4ec5e51954a83be4a1698b3ba8b58f&tag=2877e3de6e9d043a36b0cc95e111c95f&t.flac" Aug 31 08:56:59 volumio2139 volumio[1162]: info: sendMpdCommand stop took 6449 milliseconds Aug 31 08:56:59 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand clear Aug 31 08:56:59 volumio2139 volumio[1162]: info: Aug 31 08:56:59 volumio2139 volumio[1162]: ---------------------------- MPD announces system playlist update Aug 31 08:56:59 volumio2139 volumio[1162]: info: Ignoring MPD Status Update Aug 31 08:56:59 volumio2139 volumio[1162]: info: sendMpdCommand addid "http://p456ad.asuscomm.com:8096/Audio/4d4ec5e51954a83be4a1698b3ba8b58f/stream.flac?static=true&mediaSourceId=4d4ec5e51954a83be4a1698b3ba8b58f&tag=2877e3de6e9d043a36b0cc95e111c95f&t.flac" took 2 milliseconds Aug 31 08:56:59 volumio2139 volumio[1162]: verbose: MPD COMMAND [object Object] Aug 31 08:56:59 volumio2139 volumio[1162]: verbose: MPD COMMAND [object Object] Aug 31 08:56:59 volumio2139 volumio[1162]: verbose: MPD COMMAND [object Object] Aug 31 08:56:59 volumio2139 volumio[1162]: info: Aug 31 08:56:59 volumio2139 volumio[1162]: ---------------------------- MPD announces system playlist update Aug 31 08:56:59 volumio2139 volumio[1162]: info: Ignoring MPD Status Update Aug 31 08:56:59 volumio2139 volumio[1162]: error: updateQueue error: null Aug 31 08:56:59 volumio2139 volumio[1162]: info: sendMpdCommand clear took 5 milliseconds Aug 31 08:56:59 volumio2139 volumio[1162]: info: ------------------------------ 4ms Aug 31 08:56:59 volumio2139 volumio[1162]: verbose: ControllerMpd::sendMpdCommand load "http://p456ad.asuscomm.com:8096/Audio/268154c1de3727bf2649c53e71f803e1/stream.flac?static=true&mediaSourceId=268154c1de3727bf2649c53e71f803e1&tag=60918fe8e2d65bc5193f8c73f5283187&t.flac" Aug 31 08:56:59 volumio2139 volumio[1162]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 08:56:59 volumio2139 volumio[1162]: Error: [50@0] {addtagid} No such song Aug 31 08:56:59 volumio2139 volumio[1162]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:63:17) Aug 31 08:56:59 volumio2139 volumio[1162]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Aug 31 08:56:59 volumio2139 volumio[1162]: at Socket.emit (node:events:514:28) Aug 31 08:56:59 volumio2139 volumio[1162]: at addChunk (node:internal/streams/readable:343:12) Aug 31 08:56:59 volumio2139 volumio[1162]: at readableAddChunk (node:internal/streams/readable:312:11) Aug 31 08:56:59 volumio2139 volumio[1162]: at Readable.push (node:internal/streams/readable:253:10) Aug 31 08:56:59 volumio2139 volumio[1162]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Aug 31 08:56:59 volumio2139 volumio[1162]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 08:56:59 volumio2139 sudo[5486]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 08:55' Aug 31 08:56:59 volumio2139 sudo[5486]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:45:45 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6bf7cd61fe53483b72878254df87f1c0"