-- Logs begin at Thu 2019-02-14 19:11:58 JST, end at Sun 2026-02-22 10:44:48 JST. -- Feb 22 10:43:03 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetQueue Feb 22 10:43:03 primo-plus volumio[6878]: info: CoreStateMachine::getQueue Feb 22 10:43:03 primo-plus volumio[6878]: info: CorePlayQueue::getQueue Feb 22 10:43:04 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: upnp , onRestart Feb 22 10:43:04 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , onNetworkingRestart Feb 22 10:43:04 primo-plus volumio[6878]: info: Refreshing Cached IP Addresses Feb 22 10:43:04 primo-plus sudo[11922]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall upmpdcli Feb 22 10:43:04 primo-plus sudo[11922]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:04 primo-plus sudo[11922]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:04 primo-plus sudo[11925]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 22 10:43:04 primo-plus sudo[11925]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:04 primo-plus sudo[11925]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:04 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: upnp , onRestart Feb 22 10:43:04 primo-plus sudo[11928]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 22 10:43:04 primo-plus sudo[11928]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:04 primo-plus sudo[11928]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:04 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , onNetworkingRestart Feb 22 10:43:04 primo-plus volumio[6878]: info: Refreshing Cached IP Addresses Feb 22 10:43:04 primo-plus sudo[11931]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall upmpdcli Feb 22 10:43:04 primo-plus sudo[11931]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:04 primo-plus sudo[11931]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:04 primo-plus sudo[11934]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 22 10:43:04 primo-plus sudo[11934]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:04 primo-plus sudo[11934]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:04 primo-plus sudo[11937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 22 10:43:04 primo-plus sudo[11937]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:04 primo-plus systemd[1]: upmpdcli.service: Succeeded. Feb 22 10:43:04 primo-plus sudo[11937]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:04 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreStateMachine::play index 0 Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreStateMachine::stop Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:05 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:05 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:43:05 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:05 primo-plus volumio[6878]: info: [1771724585171] ControllerSpotify::clearAddPlayTrack Feb 22 10:43:05 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/play Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=debug msg="resolved context of track" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=trace msg="emitting websocket event: will_play" Feb 22 10:43:05 primo-plus volumio[6878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","play_origin":"go-librespot"}} Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=debug msg="selected format OGG_VORBIS_320 (65c725d2ce7136d39ff4d56b71a522007d58ea39)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=debug msg="requested aes key for file 65c725d2ce7136d39ff4d56b71a522007d58ea39, gid: 3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:05 primo-plus go-librespot[7136]: time="2026-02-22T10:43:05+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3tRgmNTaFYgtbt7XCy6Les: failed retrieving audio key: failed retrieving aes key with code 1" Feb 22 10:43:05 primo-plus volumio[6878]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreStateMachine::play index 0 Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreStateMachine::stop Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:11 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:11 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:43:11 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:11 primo-plus volumio[6878]: info: [1771724591308] ControllerSpotify::clearAddPlayTrack Feb 22 10:43:11 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/play Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=debug msg="resolved context of track" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=trace msg="emitting websocket event: will_play" Feb 22 10:43:11 primo-plus volumio[6878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","play_origin":"go-librespot"}} Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=debug msg="selected format OGG_VORBIS_320 (65c725d2ce7136d39ff4d56b71a522007d58ea39)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=debug msg="requested aes key for file 65c725d2ce7136d39ff4d56b71a522007d58ea39, gid: 3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:11 primo-plus go-librespot[7136]: time="2026-02-22T10:43:11+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3tRgmNTaFYgtbt7XCy6Les: failed retrieving audio key: failed retrieving aes key with code 1" Feb 22 10:43:11 primo-plus volumio[6878]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 22 10:43:12 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 22 10:43:12 primo-plus volumio[6878]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 22 10:43:12 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 22 10:43:12 primo-plus volumio[6878]: info: Received Get System Version Feb 22 10:43:12 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 22 10:43:12 primo-plus volumio[6878]: info: Received Get System Info Feb 22 10:43:12 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 22 10:43:12 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 22 10:43:12 primo-plus volumio[6878]: info: Discovery: Getting this device information Feb 22 10:43:12 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:12 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:12 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 22 10:43:14 primo-plus sudo[11954]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 22 10:43:14 primo-plus sudo[11954]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:14 primo-plus sudo[11954]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:14 primo-plus sudo[11957]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 22 10:43:14 primo-plus sudo[11957]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:14 primo-plus sudo[11957]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:14 primo-plus sudo[11960]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 22 10:43:14 primo-plus sudo[11960]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:14 primo-plus sudo[11963]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 22 10:43:14 primo-plus sudo[11963]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:14 primo-plus sudo[11963]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:14 primo-plus sudo[11967]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 22 10:43:14 primo-plus sudo[11967]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:14 primo-plus sudo[11967]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:14 primo-plus systemd[1]: Started UPnP Renderer front-end to MPD. Feb 22 10:43:14 primo-plus sudo[11960]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:14 primo-plus volumio[6878]: info: Upmpdcli Daemon Started Feb 22 10:43:14 primo-plus sudo[11970]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 22 10:43:14 primo-plus sudo[11970]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:14 primo-plus sudo[11970]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:14 primo-plus volumio[6878]: info: Upmpdcli Daemon Started Feb 22 10:43:14 primo-plus volumio[11965]: writing RSA key Feb 22 10:43:18 primo-plus go-librespot[7136]: time="2026-02-22T10:43:18+09:00" level=trace msg="sent dealer ping" Feb 22 10:43:18 primo-plus go-librespot[7136]: time="2026-02-22T10:43:18+09:00" level=trace msg="received dealer pong" Feb 22 10:43:20 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:43:20.082+09:00 level=INFO msg="navigate to next page" component=server type=REQUEST_TYPE_CONTINUE_NAVIGATION peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" latency=26.330457ms timeout=10s from=APP_PAGE_ROOT to=APP_PAGE_LEGACY_DEVICE Feb 22 10:43:20 primo-plus sudo[12016]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 22 10:43:20 primo-plus sudo[12016]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:20 primo-plus sudo[12016]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:20 primo-plus sudo[12019]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 22 10:43:20 primo-plus sudo[12019]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:20 primo-plus sudo[12019]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:20 primo-plus volumio[6878]: verbose: New Socket.io Connection to 192.168.11.14 from 192.168.11.2 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 12 Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 22 10:43:20 primo-plus sudo[12022]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 22 10:43:20 primo-plus sudo[12022]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:20 primo-plus sudo[12022]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:20 primo-plus sudo[12025]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 22 10:43:20 primo-plus sudo[12025]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:20 primo-plus sudo[12025]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:20 primo-plus volumio[6878]: verbose: New Socket.io Connection to 192.168.11.14 from 192.168.11.2 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 13 Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetVisibleSources Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:20 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 22 10:43:20 primo-plus volumio[6878]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Feb 22 10:43:20 primo-plus volumio[6878]: info: Received Get System Info Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 22 10:43:20 primo-plus volumio[6878]: info: Discovery: Getting this device information Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:20 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:20 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:20 primo-plus volumio[6878]: info: Listing playlists Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 22 10:43:20 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 22 10:43:22 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Feb 22 10:43:22 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 22 10:43:22 primo-plus volumio[6878]: info: Received Get System Info Feb 22 10:43:22 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 22 10:43:22 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 22 10:43:22 primo-plus volumio[6878]: info: Discovery: Getting this device information Feb 22 10:43:22 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:22 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:22 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 22 10:43:23 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 22 10:43:23 primo-plus volumio[6878]: info: Received Get System Info Feb 22 10:43:23 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 22 10:43:23 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 22 10:43:23 primo-plus volumio[6878]: info: Discovery: Getting this device information Feb 22 10:43:23 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:23 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:23 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 22 10:43:26 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:43:26 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:43:26 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:26 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:26 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:43:26 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:26 primo-plus volumio[6878]: info: [1771724606534] ControllerSpotify::clearAddPlayTrack Feb 22 10:43:26 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/play Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=debug msg="resolved context of track" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=trace msg="emitting websocket event: will_play" Feb 22 10:43:26 primo-plus volumio[6878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","play_origin":"go-librespot"}} Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=debug msg="selected format OGG_VORBIS_320 (65c725d2ce7136d39ff4d56b71a522007d58ea39)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=debug msg="requested aes key for file 65c725d2ce7136d39ff4d56b71a522007d58ea39, gid: 3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:26 primo-plus go-librespot[7136]: time="2026-02-22T10:43:26+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3tRgmNTaFYgtbt7XCy6Les: failed retrieving audio key: failed retrieving aes key with code 1" Feb 22 10:43:26 primo-plus volumio[6878]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:27 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:43:27 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:27 primo-plus volumio[6878]: info: [1771724607112] ControllerSpotify::clearAddPlayTrack Feb 22 10:43:27 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/play Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=debug msg="resolved context of track" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=trace msg="emitting websocket event: will_play" Feb 22 10:43:27 primo-plus volumio[6878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","play_origin":"go-librespot"}} Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=debug msg="selected format OGG_VORBIS_320 (65c725d2ce7136d39ff4d56b71a522007d58ea39)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=debug msg="requested aes key for file 65c725d2ce7136d39ff4d56b71a522007d58ea39, gid: 3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3tRgmNTaFYgtbt7XCy6Les: failed retrieving audio key: failed retrieving aes key with code 1" Feb 22 10:43:27 primo-plus volumio[6878]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:27 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:27 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:43:27 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:27 primo-plus volumio[6878]: info: [1771724607917] ControllerSpotify::clearAddPlayTrack Feb 22 10:43:27 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/play Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=debug msg="resolved context of track" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:27 primo-plus go-librespot[7136]: time="2026-02-22T10:43:27+09:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:28 primo-plus go-librespot[7136]: time="2026-02-22T10:43:28+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 10:43:28 primo-plus go-librespot[7136]: time="2026-02-22T10:43:28+09:00" level=trace msg="emitting websocket event: will_play" Feb 22 10:43:28 primo-plus volumio[6878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","play_origin":"go-librespot"}} Feb 22 10:43:28 primo-plus go-librespot[7136]: time="2026-02-22T10:43:28+09:00" level=debug msg="selected format OGG_VORBIS_320 (65c725d2ce7136d39ff4d56b71a522007d58ea39)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:28 primo-plus go-librespot[7136]: time="2026-02-22T10:43:28+09:00" level=debug msg="requested aes key for file 65c725d2ce7136d39ff4d56b71a522007d58ea39, gid: 3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:28 primo-plus go-librespot[7136]: time="2026-02-22T10:43:28+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3tRgmNTaFYgtbt7XCy6Les: failed retrieving audio key: failed retrieving aes key with code 1" Feb 22 10:43:28 primo-plus volumio[6878]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 22 10:43:30 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Feb 22 10:43:32 primo-plus volumio[6878]: info: MCU Signalled Sleep Mode Disabled Feb 22 10:43:32 primo-plus sudo[12042]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms force on Feb 22 10:43:32 primo-plus sudo[12042]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:43:32 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:43:32 primo-plus sudo[12042]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:32 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:32 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:43:32 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:43:32 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:32 primo-plus volumio[6878]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received inputs Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::volumiosetSourceActiveno-source Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 22 10:43:32 primo-plus volumio[6878]: Cannot find translation for source Spotify Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:43:32 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:32 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:32 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:43:32 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:43:32 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:43:32 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:32 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:32 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:43:32 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:43:32 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:43:32.155+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_STOPPED positionMs=4203 volume=47 Feb 22 10:43:32 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:43:32.155+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=spotify:track:3tRgmNTaFYgtbt7XCy6Les title="Same Blue" Feb 22 10:43:32 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:43:32.155+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_STOPPED positionMs=4203 volume=47 Feb 22 10:43:32 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:43:32.156+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=spotify:track:3tRgmNTaFYgtbt7XCy6Les title="Same Blue" Feb 22 10:43:32 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:43:32.155+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_STOPPED positionMs=4203 volume=47 Feb 22 10:43:32 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:43:32.156+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=spotify:track:3tRgmNTaFYgtbt7XCy6Les title="Same Blue" Feb 22 10:43:32 primo-plus volumio[6878]: error: Serial API: Failed to decode command: LEDCOLOR, message: 2 Feb 22 10:43:32 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 22 10:43:32 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Feb 22 10:43:32 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:43:32 primo-plus volumio[6878]: SPOTIFY: SPOTIFY VOLUME 0 Feb 22 10:43:32 primo-plus volumio[6878]: SPOTIFY: VOLUMIO VOLUME 47 Feb 22 10:43:32 primo-plus volumio[6878]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 22 10:43:32 primo-plus volumio[6878]: info: Setting Spotify Volume from Volumio: 47 Feb 22 10:43:32 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:43:32 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:43:32 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:43:32 primo-plus sudo[12045]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/xset dpms 0 0 0 Feb 22 10:43:32 primo-plus sudo[12045]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 22 10:43:32 primo-plus sudo[12045]: pam_unix(sudo:session): session closed for user root Feb 22 10:43:33 primo-plus volumio[6878]: SPOTIFY: SETTING SPOTIFY VOLUME 47 Feb 22 10:43:33 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/volume Feb 22 10:43:33 primo-plus go-librespot[7136]: time="2026-02-22T10:43:33+09:00" level=debug msg="update volume requested to 30801/65535" Feb 22 10:43:33 primo-plus go-librespot[7136]: time="2026-02-22T10:43:33+09:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 22 10:43:33 primo-plus go-librespot[7136]: time="2026-02-22T10:43:33+09:00" level=trace msg="emitting websocket event: volume" Feb 22 10:43:33 primo-plus volumio[6878]: SPOTIFY: received: {"type":"volume","data":{"value":47,"max":100}} Feb 22 10:43:33 primo-plus volumio[6878]: SPOTIFY: RECEIVED SPOTIFY VOLUME 47 Feb 22 10:43:34 primo-plus go-librespot[7136]: time="2026-02-22T10:43:34+09:00" level=trace msg="received accesspoint ping" Feb 22 10:43:34 primo-plus go-librespot[7136]: time="2026-02-22T10:43:34+09:00" level=trace msg="received accesspoint pong ack" Feb 22 10:43:34 primo-plus volumio[6878]: info: Executing endpoint metavolumio Feb 22 10:43:34 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 22 10:43:34 primo-plus volumio[6878]: info: Executing endpoint metavolumio Feb 22 10:43:34 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 22 10:43:34 primo-plus volumio[6878]: info: Executing endpoint metavolumio Feb 22 10:43:34 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Feb 22 10:43:35 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:43:35 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:43:35 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:43:35 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:35 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:43:35 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:35 primo-plus volumio[6878]: info: [1771724615072] ControllerSpotify::clearAddPlayTrack Feb 22 10:43:35 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/play Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=debug msg="resolved context of track" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=trace msg="emitting websocket event: will_play" Feb 22 10:43:35 primo-plus volumio[6878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","play_origin":"go-librespot"}} Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=debug msg="selected format OGG_VORBIS_320 (65c725d2ce7136d39ff4d56b71a522007d58ea39)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=debug msg="requested aes key for file 65c725d2ce7136d39ff4d56b71a522007d58ea39, gid: 3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:43:35 primo-plus go-librespot[7136]: time="2026-02-22T10:43:35+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3tRgmNTaFYgtbt7XCy6Les: failed retrieving audio key: failed retrieving aes key with code 1" Feb 22 10:43:35 primo-plus volumio[6878]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 22 10:43:39 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 22 10:43:39 primo-plus volumio[6878]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 22 10:43:39 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 22 10:43:39 primo-plus volumio[6878]: info: Received Get System Version Feb 22 10:43:39 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 22 10:43:39 primo-plus volumio[6878]: info: Received Get System Info Feb 22 10:43:39 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 22 10:43:39 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 22 10:43:39 primo-plus volumio[6878]: info: Discovery: Getting this device information Feb 22 10:43:39 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:39 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:39 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 22 10:43:42 primo-plus volumio[6878]: verbose: New Socket.io Connection to 192.168.11.14 from 192.168.11.2 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 11 Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetVisibleSources Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:42 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 22 10:43:42 primo-plus volumio[6878]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: inputs , handleBrowseUri Feb 22 10:43:42 primo-plus volumio[6878]: info: Received Get System Info Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 22 10:43:42 primo-plus volumio[6878]: info: Discovery: Getting this device information Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:42 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:43:42 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:43:42 primo-plus volumio[6878]: info: Listing playlists Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetQueue Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreStateMachine::getQueue Feb 22 10:43:42 primo-plus volumio[6878]: info: CorePlayQueue::getQueue Feb 22 10:43:42 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Feb 22 10:43:48 primo-plus go-librespot[7136]: time="2026-02-22T10:43:48+09:00" level=trace msg="sent dealer ping" Feb 22 10:43:48 primo-plus go-librespot[7136]: time="2026-02-22T10:43:48+09:00" level=trace msg="received dealer pong" Feb 22 10:44:08 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:44:08 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:44:08 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:44:08 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:08 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:44:08 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:08 primo-plus volumio[6878]: info: [1771724648815] ControllerSpotify::clearAddPlayTrack Feb 22 10:44:08 primo-plus volumio[6878]: info: Sending Spotify command with payload to local API: /player/play Feb 22 10:44:08 primo-plus go-librespot[7136]: time="2026-02-22T10:44:08+09:00" level=debug msg="resolved context of track" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:44:08 primo-plus go-librespot[7136]: time="2026-02-22T10:44:08+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:44:08 primo-plus go-librespot[7136]: time="2026-02-22T10:44:08+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:44:08 primo-plus go-librespot[7136]: time="2026-02-22T10:44:08+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 22 10:44:08 primo-plus go-librespot[7136]: time="2026-02-22T10:44:08+09:00" level=trace msg="emitting websocket event: will_play" Feb 22 10:44:08 primo-plus volumio[6878]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","uri":"spotify:track:3tRgmNTaFYgtbt7XCy6Les","play_origin":"go-librespot"}} Feb 22 10:44:09 primo-plus go-librespot[7136]: time="2026-02-22T10:44:09+09:00" level=debug msg="selected format OGG_VORBIS_320 (65c725d2ce7136d39ff4d56b71a522007d58ea39)" uri="spotify:track:3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:44:09 primo-plus go-librespot[7136]: time="2026-02-22T10:44:09+09:00" level=debug msg="requested aes key for file 65c725d2ce7136d39ff4d56b71a522007d58ea39, gid: 3tRgmNTaFYgtbt7XCy6Les" Feb 22 10:44:09 primo-plus go-librespot[7136]: time="2026-02-22T10:44:09+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:3tRgmNTaFYgtbt7XCy6Les: failed retrieving audio key: failed retrieving aes key with code 1" Feb 22 10:44:09 primo-plus volumio[6878]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Feb 22 10:44:12 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetQueue Feb 22 10:44:12 primo-plus volumio[6878]: info: CoreStateMachine::getQueue Feb 22 10:44:12 primo-plus volumio[6878]: info: CorePlayQueue::getQueue Feb 22 10:44:17 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Feb 22 10:44:17 primo-plus volumio[6878]: info: CURURI: genres:// Feb 22 10:44:17 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:18 primo-plus go-librespot[7136]: time="2026-02-22T10:44:18+09:00" level=trace msg="sent dealer ping" Feb 22 10:44:18 primo-plus go-librespot[7136]: time="2026-02-22T10:44:18+09:00" level=trace msg="received dealer pong" Feb 22 10:44:23 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Feb 22 10:44:23 primo-plus volumio[6878]: info: CURURI: music-library Feb 22 10:44:23 primo-plus volumio[6878]: error: Failed LSINFO: null Feb 22 10:44:23 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:30 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Feb 22 10:44:30 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:34 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Feb 22 10:44:34 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 22 10:44:34 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:37 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Feb 22 10:44:37 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:39 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: webradio , handleBrowseUri Feb 22 10:44:41 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:43 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::volumioReplaceandPlayItems Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::ClearQueue Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::stop Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:44:43 primo-plus volumio[6878]: info: CorePlayQueue::clearPlayQueue Feb 22 10:44:43 primo-plus volumio[6878]: info: CorePlayQueue::saveQueue Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushQueue Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::addQueueItems Feb 22 10:44:43 primo-plus volumio[6878]: info: CorePlayQueue::addQueueItems Feb 22 10:44:43 primo-plus volumio[6878]: info: Preload queue cleared Feb 22 10:44:43 primo-plus volumio[6878]: info: Adding Item to queue: http://yp.shoutcast.com/sbin/tunein-station.m3u?id=99568320 Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushQueue Feb 22 10:44:43 primo-plus volumio[6878]: info: CorePlayQueue::saveQueue Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::updateTrackBlock Feb 22 10:44:43 primo-plus volumio[6878]: info: CorePlayQueue::getTrackBlock Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPlay Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::play index 0 Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::stop Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::play index undefined Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 22 10:44:43 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreStateMachine::startPlaybackTimer Feb 22 10:44:43 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetVisibleSources Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 22 10:44:43 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 22 10:44:43 primo-plus volumio[6878]: info: [1771724683592] ControllerWebradio::clearAddPlayTrack Feb 22 10:44:43 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand stop Feb 22 10:44:43 primo-plus volumio[6878]: info: sendMpdCommand stop took 6 milliseconds Feb 22 10:44:43 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand clear Feb 22 10:44:43 primo-plus volumio[6878]: info: sendMpdCommand clear took 1 milliseconds Feb 22 10:44:43 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=99568320" Feb 22 10:44:43 primo-plus volumio[6878]: info: Feb 22 10:44:43 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:43 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:43 primo-plus volumio[6878]: info: Feb 22 10:44:43 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:43 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:43 primo-plus volumio[6878]: info: Feb 22 10:44:43 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:43 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:43 primo-plus volumio[6878]: error: Upnp client error: Error: This socket has been ended by the other party Feb 22 10:44:44 primo-plus volumio[6878]: info: Feb 22 10:44:44 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:44 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:44 primo-plus volumio[6878]: info: sendMpdCommand load "http://yp.shoutcast.com/sbin/tunein-station.m3u?id=99568320" took 1048 milliseconds Feb 22 10:44:44 primo-plus volumio[6878]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 22 10:44:44 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand play Feb 22 10:44:44 primo-plus volumio[6878]: info: ------------------------------ 1052ms Feb 22 10:44:44 primo-plus volumio[6878]: info: ------------------------------ 1049ms Feb 22 10:44:44 primo-plus volumio[6878]: info: ------------------------------ 1048ms Feb 22 10:44:44 primo-plus volumio[6878]: info: Feb 22 10:44:44 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:44 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:44 primo-plus volumio[6878]: info: Feb 22 10:44:44 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:44 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:44 primo-plus volumio[6878]: info: ------------------------------ 11ms Feb 22 10:44:44 primo-plus volumio[6878]: info: sendMpdCommand play took 9 milliseconds Feb 22 10:44:44 primo-plus volumio[6878]: info: ------------------------------ 3ms Feb 22 10:44:44 primo-plus volumio[6878]: info: ------------------------------ 3ms Feb 22 10:44:46 primo-plus volumio[6878]: info: Feb 22 10:44:46 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:46 primo-plus volumio[6878]: info: Feb 22 10:44:46 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:46 primo-plus volumio[6878]: info: Feb 22 10:44:46 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:46 primo-plus volumio[6878]: info: Feb 22 10:44:46 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand status took 9 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand status took 5 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:46 primo-plus volumio[6878]: info: Feb 22 10:44:46 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:46 primo-plus volumio[6878]: info: Feb 22 10:44:46 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand status took 17 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand status took 16 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 12 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 12 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand status took 10 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand status took 4 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"dance.mp3","artist":"(#1 - 5976/32000) Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:46 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus stop Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"dance.mp3","artist":"(#1 - 5976/32000) Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:46 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:46 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: ------------------------------ 49ms Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.798+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.798+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.798+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.799+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio[6878]: info: ------------------------------ 57ms Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 35 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 35 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 32 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 32 milliseconds Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:46 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"dance.mp3","artist":"(#1 - 5976/32000) Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:46 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:46 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"dance.mp3","artist":"(#1 - 5976/32000) Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:46 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:46 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"dance.mp3","artist":"(#1 - 5976/32000) Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:46 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:46 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"dance.mp3","artist":"(#1 - 5976/32000) Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:46 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:46 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:46 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:46 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.863+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.863+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.867+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.868+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.869+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.869+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.869+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.870+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.870+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.870+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.871+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.871+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.871+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=0 volume=47 Feb 22 10:44:46 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:46.872+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="Dance Wave!" Feb 22 10:44:46 primo-plus volumio[6878]: info: ------------------------------ 129ms Feb 22 10:44:46 primo-plus volumio[6878]: info: ------------------------------ 128ms Feb 22 10:44:46 primo-plus volumio[6878]: info: ------------------------------ 122ms Feb 22 10:44:46 primo-plus volumio[6878]: info: ------------------------------ 125ms Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:46 primo-plus volumio[6878]: info: MCU Signalled Playback Active Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:47 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:47 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:47 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:47 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 5ms Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand status took 5 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 4ms Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand status took 4 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 3ms Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand status took 2 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:47 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces system playlist update Feb 22 10:44:47 primo-plus volumio[6878]: info: Ignoring MPD Status Update Feb 22 10:44:47 primo-plus volumio[6878]: info: Feb 22 10:44:47 primo-plus volumio[6878]: ---------------------------- MPD announces state update: player Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::getState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand status Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 7ms Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand status took 6 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 4 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 4 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 5 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 4ms Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand status took 4 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 3ms Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand status took 3 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseState Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:47 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1093,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:47 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:47 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:47 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1105,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:47 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:47 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:47 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1105,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:47 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:47 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.064+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.064+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.066+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.066+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.066+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.066+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.066+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.067+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.067+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.068+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.072+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.072+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 62ms Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 62ms Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 62ms Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 53 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 53 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: info: sendMpdCommand playlistinfo took 53 milliseconds Feb 22 10:44:47 primo-plus volumio[6878]: verbose: ControllerMpd::parseTrackInfo Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:47 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1105,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:47 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:47 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:47 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1105,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:47 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:47 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: ControllerMpd::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::servicePushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CorePlayQueue::getTrack 0 Feb 22 10:44:47 primo-plus volumio[6878]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1105,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"112 Kbps","isStreaming":false,"title":"All about Dance from 2000 till today!","artist":"Dance Wave!","album":null,"uri":"https://dancewave.online:443/dance.mp3","trackType":"mp3"} Feb 22 10:44:47 primo-plus volumio[6878]: verbose: CURRENT POSITION 0 Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState stateService play Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::syncState currentStatus play Feb 22 10:44:47 primo-plus volumio[6878]: info: Received an update from plugin. extracting info from payload Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreStateMachine::pushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioPushState Feb 22 10:44:47 primo-plus volumio[6878]: info: CoreCommandRouter::volumioGetState Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output update for this device Feb 22 10:44:47 primo-plus volumio[6878]: info: MRS: Pushing multiroomSync output Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.120+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.120+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.120+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.121+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.122+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.122+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.123+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.124+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" state=STATUS_PLAYING positionMs=277 volume=47 Feb 22 10:44:47 primo-plus volumio5-onboarding[1437]: time=2026-02-22T10:44:47.124+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.11.2:59973,192.168.11.2:59979 @ 0x349a030" id=https://dancewave.online:443/dance.mp3 title="All about Dance from 2000 till today!" Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 107ms Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 105ms Feb 22 10:44:47 primo-plus volumio[6878]: info: ------------------------------ 105ms Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: info: Signalling Playback active due to playback status change Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:47 primo-plus volumio[6878]: info: Updating RAAT Signal Path Feb 22 10:44:48 primo-plus go-librespot[7136]: time="2026-02-22T10:44:48+09:00" level=trace msg="sent dealer ping" Feb 22 10:44:48 primo-plus go-librespot[7136]: time="2026-02-22T10:44:48+09:00" level=trace msg="received dealer pong" Feb 22 10:44:48 primo-plus volumio[6878]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 22 10:44:48 primo-plus volumio[6878]: TypeError: Cannot read property 'slice' of null Feb 22 10:44:48 primo-plus volumio[6878]: at download (/volumio/app/plugins/miscellanea/albumart/albumart.js:718:41) Feb 22 10:44:48 primo-plus volumio[6878]: at ClientRequest. (/volumio/app/plugins/miscellanea/albumart/albumart.js:728:7) Feb 22 10:44:48 primo-plus volumio[6878]: at Object.onceWrapper (events.js:422:26) Feb 22 10:44:48 primo-plus volumio[6878]: at ClientRequest.emit (events.js:315:20) Feb 22 10:44:48 primo-plus volumio[6878]: at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:641:27) Feb 22 10:44:48 primo-plus volumio[6878]: at HTTPParser.parserOnHeadersComplete (_http_common.js:126:17) Feb 22 10:44:48 primo-plus volumio[6878]: at TLSSocket.socketOnData (_http_client.js:509:22) Feb 22 10:44:48 primo-plus volumio[6878]: at TLSSocket.emit (events.js:315:20) Feb 22 10:44:48 primo-plus volumio[6878]: at addChunk (internal/streams/readable.js:309:12) Feb 22 10:44:48 primo-plus volumio[6878]: at readableAddChunk (internal/streams/readable.js:284:9) Feb 22 10:44:48 primo-plus volumio[6878]: at TLSSocket.Readable.push (internal/streams/readable.js:223:10) Feb 22 10:44:48 primo-plus volumio[6878]: at TLSWrap.onStreamRead (internal/stream_base_commons.js:188:23) Feb 22 10:44:48 primo-plus volumio[6878]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 22 10:44:48 primo-plus sudo[12225]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-22 10:43 Feb 22 10:44:48 primo-plus sudo[12225]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="e9612ec5034fb2e958508aaefbca2962fd6f6654" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="primoplus" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 05 Feb 2026 04:01:29 PM CET" VOLUMIO_VERSION="3.908" VOLUMIO_HARDWARE="cm4" VOLUMIO_DEVICENAME="CM4" VOLUMIO_VENDOR_MODEL="Volumio Primo Plus" VOLUMIO_VENDOR="Volumio" VOLUMIO_MODEL="Primo Plus" VOLUMIO_HASH="048051fc95e30092a9f7a83497492604"