-- Logs begin at Thu 2019-02-14 18:11:58 CST, end at Sat 2026-04-11 21:04:19 CST. -- Apr 11 21:03:06 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 11 21:03:11 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: multiroom , disableAudioOutput Apr 11 21:03:11 primo volumio[17244]: info: MRS: Starting browser stream Apr 11 21:03:11 primo volumio[17244]: info: MRS: Setting this device as single Apr 11 21:03:11 primo volumio[17244]: info: Apr 11 21:03:11 primo volumio[17244]: [1775912591637] ---------------------------- Setting Multiroom Single Apr 11 21:03:11 primo volumio[17244]: info: MRS: disable multiroom output Apr 11 21:03:11 primo volumio[17244]: info: MRS: Set multiroom target PCM to volumioDiscard Apr 11 21:03:11 primo volumio[17244]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioDiscard Apr 11 21:03:12 primo volumio[17244]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Apr 11 21:03:12 primo volumio[17244]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioLocalPlayback Apr 11 21:03:13 primo volumio[17244]: info: MRS: STOPPING volumioStreaming Apr 11 21:03:13 primo sudo[24495]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Apr 11 21:03:13 primo sudo[24495]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 21:03:13 primo systemd[1]: Stopping VolumioStreamingService... Apr 11 21:03:13 primo systemd[1]: volumioStreaming.service: Main process exited, code=killed, status=15/TERM Apr 11 21:03:13 primo volumio[17244]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 11 21:03:13 primo systemd[1]: volumioStreaming.service: Succeeded. Apr 11 21:03:13 primo systemd[1]: Stopped VolumioStreamingService. Apr 11 21:03:13 primo sudo[24498]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Apr 11 21:03:13 primo sudo[24498]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 21:03:13 primo sudo[24498]: pam_unix(sudo:session): session closed for user root Apr 11 21:03:13 primo sudo[24495]: pam_unix(sudo:session): session closed for user root Apr 11 21:03:13 primo volumio[17244]: info: MRS: Removed streaming files Apr 11 21:03:13 primo volumio[17244]: info: MRS: volumioStreaming STOPPED Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 11 21:03:15 primo volumio[17244]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 11 21:03:15 primo volumio[17244]: info: Received Get System Version Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 11 21:03:15 primo volumio[17244]: info: Received Get System Info Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:15 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:15 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:15 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:15 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:15 primo volumio[17244]: verbose: New Socket.io Connection to 192.168.0.108:3000 from 192.168.0.205 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:15 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:15 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:15 primo volumio[17244]: verbose: New Socket.io Connection to 192.168.0.115:3000 from 192.168.0.205 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 11 21:03:15 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 11 21:03:17 primo go-librespot[13675]: time="2026-04-11T21:03:17+08:00" level=error msg="did not receive last pong from dealer, 55s passed" Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:19 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:19 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:19 primo volumio[17244]: verbose: New Socket.io Connection to 192.168.0.108:3000 from 192.168.0.205 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:19 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:19 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:19 primo volumio[17244]: verbose: New Socket.io Connection to 192.168.0.115:3000 from 192.168.0.205 UA: Dart/3.10 (dart:io) Engine version: 3 Transport: websocket Total Clients: 12 Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 11 21:03:19 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 11 21:03:21 primo go-librespot[13675]: time="2026-04-11T21:03:21+08:00" level=debug msg="received connection id: YTIyYWM4MmMtMmY5...QzU2MzJDNkQxNQ==" Apr 11 21:03:21 primo go-librespot[13675]: time="2026-04-11T21:03:21+08:00" level=error msg="failed handling request play" error="failed resolving context: spclient request failed: context deadline exceeded" Apr 11 21:03:21 primo go-librespot[13675]: time="2026-04-11T21:03:21+08:00" level=error msg="failed receiving dealer message" error="failed to get reader: use of closed network connection" Apr 11 21:03:21 primo volumio[17244]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Apr 11 21:03:22 primo go-librespot[13675]: time="2026-04-11T21:03:22+08:00" level=debug msg="dealer connection opened" Apr 11 21:03:22 primo go-librespot[13675]: time="2026-04-11T21:03:22+08:00" level=debug msg="re-established dealer connection" Apr 11 21:03:27 primo volumio[17244]: info: CoreCommandRouter::volumioPlay Apr 11 21:03:27 primo volumio[17244]: info: CoreStateMachine::play index undefined Apr 11 21:03:27 primo volumio[17244]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 11 21:03:27 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:27 primo volumio[17244]: info: CoreStateMachine::startPlaybackTimer Apr 11 21:03:27 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:27 primo volumio[17244]: info: [1775912607691] ControllerSpotify::clearAddPlayTrack Apr 11 21:03:27 primo volumio[17244]: info: Sending Spotify command with payload to local API: /player/play Apr 11 21:03:30 primo volumio[17244]: info: CoreCommandRouter::volumioPlay Apr 11 21:03:30 primo volumio[17244]: info: CoreStateMachine::play index undefined Apr 11 21:03:30 primo volumio[17244]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 11 21:03:30 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:30 primo volumio[17244]: info: CoreStateMachine::startPlaybackTimer Apr 11 21:03:30 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:30 primo volumio[17244]: info: [1775912610483] ControllerSpotify::clearAddPlayTrack Apr 11 21:03:30 primo volumio[17244]: info: Sending Spotify command with payload to local API: /player/play Apr 11 21:03:37 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:37.622+08:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" latency=407.646193ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Apr 11 21:03:37 primo sudo[24588]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 11 21:03:37 primo sudo[24588]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 21:03:38 primo sudo[24588]: pam_unix(sudo:session): session closed for user root Apr 11 21:03:38 primo sudo[24592]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 11 21:03:38 primo sudo[24592]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 21:03:38 primo sudo[24592]: pam_unix(sudo:session): session closed for user root Apr 11 21:03:38 primo volumio[17244]: verbose: New Socket.io Connection to 192.168.0.108 from 192.168.0.205 UA: Mozilla/5.0 (Linux; Android 16; V2413 Build/BQ2A.250610.001-BP2A.250605.031.A3_V000L1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.177 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 11 21:03:38 primo sudo[24596]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 11 21:03:38 primo sudo[24596]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 21:03:38 primo sudo[24596]: pam_unix(sudo:session): session closed for user root Apr 11 21:03:38 primo sudo[24600]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 11 21:03:38 primo sudo[24600]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 21:03:38 primo sudo[24600]: pam_unix(sudo:session): session closed for user root Apr 11 21:03:38 primo volumio[17244]: verbose: New Socket.io Connection to 192.168.0.108 from 192.168.0.205 UA: Mozilla/5.0 (Linux; Android 16; V2413 Build/BQ2A.250610.001-BP2A.250605.031.A3_V000L1; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/146.0.7680.177 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::volumioGetVisibleSources Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:38 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 11 21:03:38 primo volumio[17244]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Apr 11 21:03:38 primo volumio[17244]: info: Received Get System Info Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:38 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:38 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:38 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:38 primo volumio[17244]: info: Listing playlists Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 21:03:38 primo volumio[17244]: info: FusionDsp - Apr 11 21:03:38 primo volumio[17244]: info: FusionDsp - undefined Apr 11 21:03:38 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Apr 11 21:03:39 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Apr 11 21:03:40 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 11 21:03:40 primo volumio[17244]: info: Received Get System Info Apr 11 21:03:40 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:40 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:40 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:40 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:40 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:40 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:41 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 11 21:03:41 primo volumio[17244]: info: Received Get System Info Apr 11 21:03:41 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:41 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:41 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:41 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:41 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:41 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 21:03:45 primo volumio[17244]: info: Retrieving Cloud Streaming UI Apr 11 21:03:45 primo volumio[17244]: info: Getting Tidal Cloud Configuration Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 21:03:45 primo volumio[17244]: info: Getting Qobuz Cloud Configuration Apr 11 21:03:45 primo volumio[17244]: info: Asking plugin for UI Config Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 21:03:45 primo volumio[17244]: info: Getting Spotify Cloud Configuration Apr 11 21:03:45 primo volumio[17244]: info: Asking plugin for UI Config Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 21:03:45 primo volumio[17244]: info: Saving Spotify Acccount Apr 11 21:03:45 primo volumio[17244]: info: Got it Apr 11 21:03:45 primo volumio[17244]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Apr 11 21:03:45 primo volumio[17244]: info: Got Tidal Cloud Configuration Apr 11 21:03:45 primo volumio[17244]: info: Got it Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::volumioGetBrowseSources Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::volumioGetBrowseSources Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::volumioGetBrowseSources Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:03:45 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Apr 11 21:03:47 primo go-librespot[13675]: time="2026-04-11T21:03:47+08:00" level=trace msg="sent dealer ping" Apr 11 21:03:48 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 11 21:03:49 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:03:51 primo go-librespot[13675]: time="2026-04-11T21:03:51+08:00" level=warning msg="failed handling dealer message" error="failed initial state put: context deadline exceeded" Apr 11 21:03:51 primo go-librespot[13675]: time="2026-04-11T21:03:51+08:00" level=debug msg="received connection id: ZTZiNDMxNTItYzAw...MkQxQjZDQzgwRQ==" Apr 11 21:03:51 primo go-librespot[13675]: time="2026-04-11T21:03:51+08:00" level=trace msg="received dealer pong" Apr 11 21:03:53 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand update Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: Apr 11 21:03:54 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand update took 15 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: Apr 11 21:03:54 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: Apr 11 21:03:54 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 29 milliseconds Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: Apr 11 21:03:54 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 109 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 109 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 107 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 106 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 105 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:54 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:54 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.728+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.728+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.728+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.729+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.729+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.729+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:54 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:54 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:54 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:54 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:54 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:54 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:54 primo volumio[17244]: info: ------------------------------ 318ms Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.771+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.771+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.771+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.772+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.772+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.773+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.774+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.775+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.779+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=24059 volume=63 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.780+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.780+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:54.780+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:54 primo volumio[17244]: info: ------------------------------ 335ms Apr 11 21:03:54 primo volumio[17244]: info: ------------------------------ 334ms Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: Apr 11 21:03:54 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: Apr 11 21:03:54 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:54 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:54 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:54 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:54 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 285 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 285 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 58 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 56 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 55 milliseconds Apr 11 21:03:54 primo volumio[17244]: info: sendMpdCommand status took 53 milliseconds Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:54 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:54 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:55 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:55 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:55 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:55 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:55 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:55 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:55 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:55 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:55 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:55 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:55 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:55 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:55 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:55 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:55 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:55 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:55 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.169+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.169+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.170+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.170+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.170+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.170+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.174+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.175+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.175+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.175+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.176+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.176+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.178+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.178+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.179+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=24343 volume=63 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.179+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.179+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:55.180+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:55 primo volumio[17244]: info: ------------------------------ 642ms Apr 11 21:03:55 primo volumio[17244]: info: ------------------------------ 410ms Apr 11 21:03:55 primo volumio[17244]: info: ------------------------------ 407ms Apr 11 21:03:55 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:55 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:55 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand rescan Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: Apr 11 21:03:56 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand rescan took 8 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: Apr 11 21:03:56 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: Apr 11 21:03:56 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 13 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 12 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 10 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 10 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 10 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 8 milliseconds Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:56 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:56 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:56 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:56 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:56 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:56 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:56 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:56 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:56 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.888+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.888+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.888+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.889+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.889+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.889+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.892+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.892+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.892+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.892+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.893+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.893+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.894+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.895+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.895+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=25963 volume=63 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.896+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.897+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:56.897+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:56 primo volumio[17244]: info: ------------------------------ 271ms Apr 11 21:03:56 primo volumio[17244]: info: ------------------------------ 268ms Apr 11 21:03:56 primo volumio[17244]: info: ------------------------------ 266ms Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: Apr 11 21:03:56 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 11 21:03:56 primo volumio[17244]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 11 21:03:56 primo volumio[17244]: info: Received Get System Version Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 11 21:03:56 primo volumio[17244]: info: Received Get System Info Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 11 21:03:56 primo volumio[17244]: info: Discovery: Getting this device information Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:56 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:56 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: Apr 11 21:03:56 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: Apr 11 21:03:56 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:56 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:56 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:56 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:56 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 63 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 61 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 47 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 45 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 45 milliseconds Apr 11 21:03:56 primo volumio[17244]: info: sendMpdCommand status took 44 milliseconds Apr 11 21:03:56 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:57 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:57 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:57 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.210+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.210+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.210+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.211+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.212+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.212+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.213+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.213+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.214+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.214+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.215+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.215+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.216+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.216+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.217+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=26417 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.217+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.218+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.218+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio[17244]: info: ------------------------------ 312ms Apr 11 21:03:57 primo volumio[17244]: info: ------------------------------ 296ms Apr 11 21:03:57 primo volumio[17244]: info: ------------------------------ 294ms Apr 11 21:03:57 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:57 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:57 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand rescan Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: info: Apr 11 21:03:57 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand rescan took 7 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: info: Apr 11 21:03:57 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: info: Apr 11 21:03:57 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: info: Apr 11 21:03:57 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 13 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 12 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 11 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 12 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 12 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 11 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:57 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:57 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:57 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:57 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:57 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:57 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:57 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.913+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.914+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.914+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.915+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.915+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.915+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.915+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.915+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.915+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.916+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.916+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.916+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.918+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.918+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.919+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=27001 volume=63 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.919+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.920+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:57.920+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:57 primo volumio[17244]: info: ------------------------------ 266ms Apr 11 21:03:57 primo volumio[17244]: info: ------------------------------ 264ms Apr 11 21:03:57 primo volumio[17244]: info: ------------------------------ 262ms Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: info: Apr 11 21:03:57 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: info: Apr 11 21:03:57 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:57 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 268 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 262 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 12 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 11 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 10 milliseconds Apr 11 21:03:57 primo volumio[17244]: info: sendMpdCommand status took 9 milliseconds Apr 11 21:03:57 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:58 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:58 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:58 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:58 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:58 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:58 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:58 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:58 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:58 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:58 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:58 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:58 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:58 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:58 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:58 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:58 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:58 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:58 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:58 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:58 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.176+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.176+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.176+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.176+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.176+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.177+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.177+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.177+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.177+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.177+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.177+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.177+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.179+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.179+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.181+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=27445 volume=63 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.181+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.182+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:58.182+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:58 primo volumio[17244]: info: ------------------------------ 514ms Apr 11 21:03:58 primo volumio[17244]: info: ------------------------------ 258ms Apr 11 21:03:58 primo volumio[17244]: info: ------------------------------ 255ms Apr 11 21:03:58 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:58 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:58 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:58 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:58 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:58 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand rescan Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: info: Apr 11 21:03:59 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:59 primo volumio[17244]: info: sendMpdCommand rescan took 7 milliseconds Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: info: Apr 11 21:03:59 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: info: Apr 11 21:03:59 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: info: Apr 11 21:03:59 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:59 primo volumio[17244]: info: sendMpdCommand status took 15 milliseconds Apr 11 21:03:59 primo volumio[17244]: info: sendMpdCommand status took 13 milliseconds Apr 11 21:03:59 primo volumio[17244]: info: sendMpdCommand status took 12 milliseconds Apr 11 21:03:59 primo volumio[17244]: info: sendMpdCommand status took 11 milliseconds Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: info: sendMpdCommand status took 11 milliseconds Apr 11 21:03:59 primo volumio[17244]: info: sendMpdCommand status took 9 milliseconds Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:59 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:59 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:59 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:59 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:59 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:59 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:59 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:03:59 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:03:59 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:03:59 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:03:59 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:03:59 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.966+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.967+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.967+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.968+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.968+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.968+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.971+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.972+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.972+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.972+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.972+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.972+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.972+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=29011 volume=63 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.973+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.973+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.973+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.973+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio5-onboarding[3759]: time=2026-04-11T21:03:59.973+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:03:59 primo volumio[17244]: info: ------------------------------ 276ms Apr 11 21:03:59 primo volumio[17244]: info: ------------------------------ 273ms Apr 11 21:03:59 primo volumio[17244]: info: ------------------------------ 271ms Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: info: Apr 11 21:03:59 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:03:59 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:03:59 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:00 primo volumio[17244]: info: Apr 11 21:04:00 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:04:00 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:04:00 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:00 primo volumio[17244]: info: sendMpdCommand status took 285 milliseconds Apr 11 21:04:00 primo volumio[17244]: info: sendMpdCommand status took 283 milliseconds Apr 11 21:04:00 primo volumio[17244]: info: sendMpdCommand status took 20 milliseconds Apr 11 21:04:00 primo volumio[17244]: info: sendMpdCommand status took 19 milliseconds Apr 11 21:04:00 primo volumio[17244]: info: sendMpdCommand status took 10 milliseconds Apr 11 21:04:00 primo volumio[17244]: info: sendMpdCommand status took 7 milliseconds Apr 11 21:04:00 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:00 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:00 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:00 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:00 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:00 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:00 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:00 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:00 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:00 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:00 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:00 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:00 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:00 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:00 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:00 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:00 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:00 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:00 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:00 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.239+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.239+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.240+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.240+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.241+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.241+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.242+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.243+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.244+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.244+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.244+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.245+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.245+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=29514 volume=63 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.245+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.245+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.245+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.245+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:00.246+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:00 primo volumio[17244]: info: ------------------------------ 523ms Apr 11 21:04:00 primo volumio[17244]: info: ------------------------------ 258ms Apr 11 21:04:00 primo volumio[17244]: info: ------------------------------ 246ms Apr 11 21:04:00 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:00 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:00 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:00 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:00 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:00 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:01 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , rescanDb Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand rescan Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: Apr 11 21:04:02 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand rescan took 8 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: Apr 11 21:04:02 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: Apr 11 21:04:02 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 19 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 16 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 14 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 14 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 9 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 8 milliseconds Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:02 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:02 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:02 primo volumio[17244]: info: Command Router : Notfying DB Updatetrue Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:02 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:02 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:02 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:02 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:02 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:02 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:02 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:02 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.845+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.845+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.846+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.846+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.847+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.849+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.850+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.850+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.851+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.851+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.851+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.852+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=32069 volume=63 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.852+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.852+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.852+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.852+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:02.853+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:02 primo volumio[17244]: info: ------------------------------ 261ms Apr 11 21:04:02 primo volumio[17244]: info: ------------------------------ 256ms Apr 11 21:04:02 primo volumio[17244]: info: ------------------------------ 251ms Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: Apr 11 21:04:02 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: Apr 11 21:04:02 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: Apr 11 21:04:02 primo volumio[17244]: ---------------------------- MPD announces state update: update Apr 11 21:04:02 primo volumio[17244]: info: ControllerMpd::getState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::sendMpdCommand status Apr 11 21:04:02 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:02 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 44 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 43 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 42 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 41 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 40 milliseconds Apr 11 21:04:02 primo volumio[17244]: info: sendMpdCommand status took 39 milliseconds Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:02 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:04:02 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:02 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:03 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:03 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:03 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:03 primo volumio[17244]: info: Command Router : Notfying DB Updatefalse Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::Close All Modals sent Apr 11 21:04:03 primo volumio[17244]: verbose: ControllerMpd::parseState Apr 11 21:04:03 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:03 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:03 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:03 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:03 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:03 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:03 primo volumio[17244]: info: ControllerMpd::pushState Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::servicePushState Apr 11 21:04:03 primo volumio[17244]: info: CoreStateMachine::pushState Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::volumioPushState Apr 11 21:04:03 primo volumio[17244]: info: CoreCommandRouter::volumioGetState Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: MRS: Pushing multiroomSync output update for this device Apr 11 21:04:03 primo volumio[17244]: info: MRS: Pushing multiroomSync output Apr 11 21:04:03 primo volumio[17244]: info: CorePlayQueue::getTrack 2 Apr 11 21:04:03 primo volumio[17244]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.140+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.140+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.140+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.141+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.141+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.141+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.141+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.141+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.142+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.141+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.142+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.143+08:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.143+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.144+08:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" state=STATUS_STOPPED positionMs=32364 volume=63 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.145+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%02,192.168.0.239:56800,192.168.0.239:45710 @ 0x1c0c060" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.146+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.239:45710 @ 0x18005a0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio5-onboarding[3759]: time=2026-04-11T21:04:03.146+08:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.205:55734,192.168.0.205:36014 @ 0x1c846f0" id=spotify:track:3GZWWGGSat1YWJgT6UbdaY title=眠りの森 Apr 11 21:04:03 primo volumio[17244]: info: ------------------------------ 305ms Apr 11 21:04:03 primo volumio[17244]: info: ------------------------------ 303ms Apr 11 21:04:03 primo volumio[17244]: info: ------------------------------ 301ms Apr 11 21:04:03 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:03 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:03 primo volumio[17244]: info: Updating RAAT Signal Path Apr 11 21:04:05 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:04:09 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:04:13 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:04:16 primo volumio[17244]: info: Disabling MyMusic plugin upnp Apr 11 21:04:16 primo sudo[24742]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Apr 11 21:04:16 primo sudo[24742]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 11 21:04:16 primo systemd[1]: Stopping UPnP Renderer front-end to MPD... Apr 11 21:04:16 primo volumio[17244]: error: Upnp client error: Error: This socket has been ended by the other party Apr 11 21:04:16 primo volumio[17244]: ------------------------------------ BT MESSAGE: BT STATUS: running Apr 11 21:04:17 primo go-librespot[13675]: time="2026-04-11T21:04:17+08:00" level=trace msg="sent dealer ping" Apr 11 21:04:17 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Apr 11 21:04:17 primo go-librespot[13675]: time="2026-04-11T21:04:17+08:00" level=trace msg="received dealer pong" Apr 11 21:04:18 primo volumio[17244]: info: Enabling MyMusic plugin upnp Apr 11 21:04:18 primo volumio[17244]: info: Enabling plugin upnp Apr 11 21:04:18 primo volumio[17244]: info: Loading plugin "upnp"... Apr 11 21:04:18 primo volumio[17244]: info: [1775912658564] Starting Upmpd Daemon Apr 11 21:04:18 primo volumio[17244]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 11 21:04:18 primo volumio[17244]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 11 21:04:18 primo volumio[17244]: Error: listen EADDRINUSE: address already in use :::6599 Apr 11 21:04:18 primo volumio[17244]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Apr 11 21:04:18 primo volumio[17244]: at listenInCluster (net.js:1379:12) Apr 11 21:04:18 primo volumio[17244]: at Server.listen (net.js:1465:7) Apr 11 21:04:18 primo volumio[17244]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Apr 11 21:04:18 primo volumio[17244]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Apr 11 21:04:18 primo volumio[17244]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Apr 11 21:04:18 primo volumio[17244]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Apr 11 21:04:18 primo volumio[17244]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Apr 11 21:04:18 primo volumio[17244]: code: 'EADDRINUSE', Apr 11 21:04:18 primo volumio[17244]: errno: -98, Apr 11 21:04:18 primo volumio[17244]: syscall: 'listen', Apr 11 21:04:18 primo volumio[17244]: address: '::', Apr 11 21:04:18 primo volumio[17244]: port: 6599 Apr 11 21:04:18 primo volumio[17244]: } Apr 11 21:04:18 primo volumio[17244]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 11 21:04:19 primo sudo[24753]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-04-11 21:03 Apr 11 21:04:19 primo sudo[24753]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="464fc672d77d3df6ee72b331d36cdf1fa936e1ec" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="primo2rev2" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 27 Feb 2026 12:16:07 PM CET" VOLUMIO_VERSION="3.912" VOLUMIO_HARDWARE="mp1" VOLUMIO_DEVICENAME="Volumio MP1" VOLUMIO_VENDOR_MODEL="Volumio Primo" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo" VOLUMIO_HASH="88686576587e39571d6cf25f3920fbc0"