May 27 17:58:03 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 27 17:58:03 volumio volumio[1245]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 27 17:58:03 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 27 17:58:03 volumio volumio[1245]: info: Received Get System Version May 27 17:58:03 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 27 17:58:03 volumio volumio[1245]: info: Received Get System Info May 27 17:58:03 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 27 17:58:03 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 27 17:58:03 volumio volumio[1245]: info: Discovery: Getting this device information May 27 17:58:03 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 27 17:58:03 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:04 volumio volumio[1245]: info: Getting Alsa Cards List without I2S DAC May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 27 17:58:04 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 27 17:58:16 volumio volumio[1245]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] May 27 17:58:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions May 27 17:58:16 volumio volumio[1245]: info: Preparing to save Alsa Options, stopping services first May 27 17:58:16 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 27 17:58:16 volumio volumio[1245]: info: Saving Audio Output to: {"output_device":{"value":"5","label":"USB/BT DAC-1"},"i2s":false,"i2sid":{"value":"max98357a","label":"Adafruit MAX98357"}} May 27 17:58:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:16 volumio volumio[1245]: info: Disabling I2S DAC: May 27 17:58:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , disableI2SDAC May 27 17:58:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:16 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:17 volumio volumio[1245]: info: Setting mixer PCM for card USB/BT DAC-1 May 27 17:58:17 volumio vtcs[1853]: [2026-05-27 17:58:17.148] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE May 27 17:58:17 volumio vtcs[1853]: [2026-05-27 17:58:17.157] [tisoc] [error] [SpkconServer.cpp:383] recv error. client fd=8 errorno=104 error=Connection reset by peer May 27 17:58:17 volumio vtcs[1853]: [2026-05-27 17:58:17.157] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected May 27 17:58:17 volumio sudo[2080]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:17 volumio sudo[2080]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:17 volumio volumio[1245]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 27 17:58:17 volumio volumio[1245]: info: Updating Volume Controller Parameters: Device: 5 Name: USB/BT DAC-1 Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 27 17:58:17 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 27 17:58:17 volumio volumio[1245]: info: Disabling external Volume Control May 27 17:58:17 volumio systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... May 27 17:58:17 volumio systemd[1]: vtcs.service: Killing process 1855 (vtcs) with signal SIGKILL. May 27 17:58:17 volumio systemd[1]: vtcs.service: Deactivated successfully. May 27 17:58:17 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. May 27 17:58:17 volumio sudo[2080]: pam_unix(sudo:session): session closed for user root May 27 17:58:17 volumio volumio[1245]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 17:58:17 volumio volumio[1245]: info: Preparing to generate the ALSA configuration file May 27 17:58:17 volumio sudo[2088]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:17 volumio sudo[2088]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:17 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:58:17 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:17 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:17 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:17 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:17.642+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:17 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:17.643+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=26911 volume=25 May 27 17:58:17 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:17.643+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:17 volumio sudo[2093]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l May 27 17:58:17 volumio sudo[2093]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:17 volumio sudo[2088]: pam_unix(sudo:session): session closed for user root May 27 17:58:17 volumio sudo[2093]: pam_unix(sudo:session): session closed for user root May 27 17:58:17 volumio volumio[1245]: info: No Overlays Loaded May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 27 17:58:18 volumio volumio[1245]: info: Asound.conf file written May 27 17:58:18 volumio sudo[2104]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf May 27 17:58:18 volumio sudo[2104]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:18 volumio sudo[2104]: pam_unix(sudo:session): session closed for user root May 27 17:58:18 volumio volumio[1245]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 May 27 17:58:18 volumio volumio[1245]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 May 27 17:58:18 volumio volumio[1245]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 May 27 17:58:18 volumio volumio[1245]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:3 use case configuration -2 May 27 17:58:18 volumio volumio[1245]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:4 use case configuration -2 May 27 17:58:18 volumio volumio[1245]: info: Output device has changed, restarting MPD May 27 17:58:18 volumio volumio[1245]: info: Output device has changed, restarting Shairport Sync May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:18 volumio sudo[2110]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 27 17:58:18 volumio sudo[2110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:18 volumio sudo[2112]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 27 17:58:18 volumio sudo[2110]: pam_unix(sudo:session): session closed for user root May 27 17:58:18 volumio sudo[2112]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:18 volumio volumio[1245]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 27 17:58:18 volumio volumio[1245]: info: Output device has changed, restarting MPD May 27 17:58:18 volumio systemd[1]: musicservicesshield.service: Deactivated successfully. May 27 17:58:18 volumio systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. May 27 17:58:18 volumio systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... May 27 17:58:18 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... May 27 17:58:18 volumio upmpdcli[1581]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 May 27 17:58:18 volumio sudo[2120]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:18 volumio volumio[1245]: info: Output device has changed, restarting Shairport Sync May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:18 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:18 volumio sudo[2120]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:18 volumio sudo[2126]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 27 17:58:18 volumio sudo[2126]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:18 volumio sudo[2122]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 27 17:58:18 volumio sudo[2122]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:18 volumio sudo[2122]: pam_unix(sudo:session): session closed for user root May 27 17:58:19 volumio volumio[1245]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 27 17:58:19 volumio systemd[1]: mpd.service: Deactivated successfully. May 27 17:58:19 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. May 27 17:58:19 volumio systemd[1]: mpd.service: Consumed 3.363s CPU time. May 27 17:58:19 volumio sudo[2120]: pam_unix(sudo:session): session closed for user root May 27 17:58:19 volumio systemd[1]: mpd.socket: Deactivated successfully. May 27 17:58:19 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 27 17:58:19 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 27 17:58:19 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 27 17:58:19 volumio systemd[1]: Starting mpd.service - Music Player Daemon... May 27 17:58:19 volumio systemd[1]: mpd.service: Deactivated successfully. May 27 17:58:19 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. May 27 17:58:19 volumio systemd[1]: mpd.socket: Deactivated successfully. May 27 17:58:19 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 27 17:58:19 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 27 17:58:19 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 27 17:58:19 volumio systemd[1]: Starting mpd.service - Music Player Daemon... May 27 17:58:19 volumio volumio[1245]: info: MPD Permissions set May 27 17:58:19 volumio sudo[2136]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:19 volumio volumio[1245]: info: MPD Permissions set May 27 17:58:19 volumio sudo[2139]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 27 17:58:19 volumio sudo[2139]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 27 17:58:19 volumio sudo[2136]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio sudo[2139]: pam_unix(sudo:session): session closed for user root May 27 17:58:19 volumio sudo[2143]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:19 volumio sudo[2143]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:19 volumio sudo[2141]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:19 volumio sudo[2141]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:19 volumio sudo[2136]: pam_unix(sudo:session): session closed for user root May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio sudo[2143]: pam_unix(sudo:session): session closed for user root May 27 17:58:19 volumio sudo[2141]: pam_unix(sudo:session): session closed for user root May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:19 volumio volumio[1245]: info: Starting Shairport Sync May 27 17:58:19 volumio volumio[1245]: info: Starting Shairport Sync May 27 17:58:19 volumio sudo[2164]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 27 17:58:20 volumio sudo[2164]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:20 volumio sudo[2166]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 27 17:58:20 volumio sudo[2166]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:20 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 27 17:58:20 volumio systemd[1]: shairport-sync.service: Deactivated successfully. May 27 17:58:20 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:20 volumio systemd[1]: shairport-sync.service: Consumed 1.715s CPU time. May 27 17:58:20 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:20 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 27 17:58:20 volumio sudo[2164]: pam_unix(sudo:session): session closed for user root May 27 17:58:20 volumio systemd[1]: shairport-sync.service: Deactivated successfully. May 27 17:58:20 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:20 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:20 volumio sudo[2166]: pam_unix(sudo:session): session closed for user root May 27 17:58:20 volumio volumio[1245]: info: Shairport-Sync Started May 27 17:58:20 volumio volumio[1245]: info: Shairport-Sync Started May 27 17:58:20 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:20 volumio mpd[2147]: 2026-05-27T17:58:20 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 27 17:58:20 volumio systemd[1]: Started mpd.service - Music Player Daemon. May 27 17:58:20 volumio sudo[2126]: pam_unix(sudo:session): session closed for user root May 27 17:58:20 volumio sudo[2112]: pam_unix(sudo:session): session closed for user root May 27 17:58:20 volumio volumio[1245]: error: MPD error: The expression evaluated to a falsy value: May 27 17:58:20 volumio volumio[1245]: assert.ok(self.idling) May 27 17:58:20 volumio volumio[1245]: error: The expression evaluated to a falsy value: May 27 17:58:20 volumio volumio[1245]: assert.ok(self.idling) May 27 17:58:20 volumio volumio[1245]: error: updateQueue error: null May 27 17:58:20 volumio systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... May 27 17:58:20 volumio upmpdcli[1581]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started May 27 17:58:20 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:21 volumio volumio[1245]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:21 volumio volumio[1245]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:21 volumio sudo[2207]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 27 17:58:21 volumio sudo[2207]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:21 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. May 27 17:58:21 volumio sudo[2207]: pam_unix(sudo:session): session closed for user root May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrieveVolumeLevels May 27 17:58:21 volumio volumio[1245]: info: CoreStateMachine::getcurrentVolume May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume May 27 17:58:21 volumio volumio[1245]: info: Executing endpoint tc_getconfig May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 27 17:58:21 volumio vtcs[2211]: STARTING TidalConnect services, version: 1.6.1 May 27 17:58:21 volumio vtcs[2211]: STARTED TidalConnect services. May 27 17:58:21 volumio volumio[1245]: info: Executing endpoint tc_connect May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 27 17:58:21 volumio volumio[1245]: info: Connecting to TidalConnect May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:21 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:21 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:21 volumio volumio[1245]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received tidalconnect May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:21 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:21 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:21 volumio volumio[1245]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received tidalconnect May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.545+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.546+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=30695 volume=25 May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.546+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.548+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.548+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=30695 volume=25 May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.548+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:21 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:21 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:58:21 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:21 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 27 17:58:21 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.613+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.613+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=30695 volume=25 May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.614+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:21 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:21 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:58:21 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:21 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.661+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.661+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=30991 volume=25 May 27 17:58:21 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:21.662+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:21 volumio bash[2233]: cset: --> shielding system active with May 27 17:58:21 volumio bash[2233]: cset: "system" cpuset of CPUSPEC(1-3) with 187 tasks running May 27 17:58:21 volumio bash[2233]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running May 27 17:58:21 volumio systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. May 27 17:58:22 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:22 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:22 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:22 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:22 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:22 volumio volumio[1245]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:22 volumio volumio[1245]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:22 volumio volumio[1245]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:22 volumio volumio[1245]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:23 volumio sudo[2265]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 27 17:58:23 volumio sudo[2265]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:23 volumio sudo[2267]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 27 17:58:23 volumio sudo[2267]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:23 volumio sudo[2267]: pam_unix(sudo:session): session closed for user root May 27 17:58:23 volumio sudo[2265]: pam_unix(sudo:session): session closed for user root May 27 17:58:24 volumio volumio[1245]: info: TidalConnect service started! May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 17:58:26 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 27 17:58:26 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:26 volumio volumio[1245]: info: [1779872306131] ControllerWebradio::clearAddPlayTrack May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand stop May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand stop took 1 milliseconds May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand clear May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces system playlist update May 27 17:58:26 volumio volumio[1245]: info: Ignoring MPD Status Update May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand clear took 12 milliseconds May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand add "https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8" May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces system playlist update May 27 17:58:26 volumio volumio[1245]: info: Ignoring MPD Status Update May 27 17:58:26 volumio volumio[1245]: error: updateQueue error: null May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces system playlist update May 27 17:58:26 volumio volumio[1245]: info: Ignoring MPD Status Update May 27 17:58:26 volumio volumio[1245]: info: ------------------------------ 7ms May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand add "https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8" took 7 milliseconds May 27 17:58:26 volumio volumio[1245]: info: ------------------------------ 6ms May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService mpd May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand play May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces system playlist update May 27 17:58:26 volumio volumio[1245]: info: Ignoring MPD Status Update May 27 17:58:26 volumio volumio[1245]: info: ------------------------------ 36ms May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand play took 35 milliseconds May 27 17:58:26 volumio volumio[1245]: info: ------------------------------ 35ms May 27 17:58:26 volumio volumio[1245]: info: TidalConnect service started! May 27 17:58:26 volumio volumio[1245]: info: TidalConnect service started! May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces state update: player May 27 17:58:26 volumio volumio[1245]: info: ControllerMpd::getState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand status May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces state update: player May 27 17:58:26 volumio volumio[1245]: info: ControllerMpd::getState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand status May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces state update: player May 27 17:58:26 volumio volumio[1245]: info: ControllerMpd::getState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand status May 27 17:58:26 volumio volumio[1245]: info: May 27 17:58:26 volumio volumio[1245]: ---------------------------- MPD announces state update: player May 27 17:58:26 volumio volumio[1245]: error: MPD returned error for command status: Failed to decode "https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8"; got HTTP status 404 May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand clearerror May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand status took 14 milliseconds May 27 17:58:26 volumio volumio[1245]: info: ControllerMpd::getState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand status May 27 17:58:26 volumio volumio[1245]: error: MPD returned error for command status: Failed to decode "https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8"; got HTTP status 404 May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand clearerror May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand status took 44 milliseconds May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::parseState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::parseState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 27 17:58:26 volumio volumio[1245]: error: MPD returned error for command status: Failed to decode "https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8"; got HTTP status 404 May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand clearerror May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand status took 89 milliseconds May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand clearerror took 77 milliseconds May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand status took 76 milliseconds May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand clearerror took 47 milliseconds May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand playlistinfo took 30 milliseconds May 27 17:58:26 volumio volumio[1245]: info: sendMpdCommand playlistinfo took 29 milliseconds May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::parseState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::parseState May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::parseTrackInfo May 27 17:58:26 volumio volumio[1245]: verbose: ControllerMpd::parseTrackInfo May 27 17:58:26 volumio volumio[1245]: info: ControllerMpd::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:26 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:26 volumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"chunklist.m3u8","artist":null,"album":null,"uri":"https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8","trackType":"m3u8"} May 27 17:58:26 volumio volumio[1245]: verbose: CURRENT POSITION 0 May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::syncState stateService stop May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:26 volumio volumio[1245]: info: No code May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:26 volumio volumio[1245]: info: ControllerMpd::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:26 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:26 volumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"chunklist.m3u8","artist":null,"album":null,"uri":"https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8","trackType":"m3u8"} May 27 17:58:26 volumio volumio[1245]: verbose: CURRENT POSITION 0 May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::syncState stateService stop May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:26 volumio volumio[1245]: info: No code May 27 17:58:26 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:26 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.979+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.979+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=559 volume=25 May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.979+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.981+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.981+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=559 volume=25 May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.981+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.999+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.999+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=559 volume=25 May 27 17:58:26 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:26.999+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.000+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.000+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=559 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.000+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.001+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.001+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=559 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.002+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.021+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.021+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=559 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.021+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio[1245]: info: ------------------------------ 360ms May 27 17:58:27 volumio volumio[1245]: info: ------------------------------ 360ms May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: info: sendMpdCommand clearerror took 416 milliseconds May 27 17:58:27 volumio volumio[1245]: info: sendMpdCommand playlistinfo took 432 milliseconds May 27 17:58:27 volumio volumio[1245]: info: sendMpdCommand playlistinfo took 432 milliseconds May 27 17:58:27 volumio volumio[1245]: verbose: ControllerMpd::parseTrackInfo May 27 17:58:27 volumio volumio[1245]: verbose: ControllerMpd::parseTrackInfo May 27 17:58:27 volumio volumio[1245]: info: ControllerMpd::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:27 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:27 volumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"chunklist.m3u8","artist":null,"album":null,"uri":"https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8","trackType":"m3u8"} May 27 17:58:27 volumio volumio[1245]: verbose: CURRENT POSITION 0 May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::syncState stateService stop May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:27 volumio volumio[1245]: info: No code May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:27 volumio volumio[1245]: info: ControllerMpd::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:27 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:27 volumio volumio[1245]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"chunklist.m3u8","artist":null,"album":null,"uri":"https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8","trackType":"m3u8"} May 27 17:58:27 volumio volumio[1245]: verbose: CURRENT POSITION 0 May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::syncState stateService stop May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::syncState currentStatus stop May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:27 volumio volumio[1245]: info: No code May 27 17:58:27 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:27 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.367+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.367+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1155 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.367+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.382+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.382+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1155 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.382+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.383+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.383+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1155 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.383+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.384+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.384+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1155 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.385+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.406+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.406+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1155 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.407+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.407+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.407+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1155 volume=25 May 27 17:58:27 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:27.407+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:27 volumio volumio[1245]: info: ------------------------------ 749ms May 27 17:58:27 volumio volumio[1245]: info: ------------------------------ 748ms May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:27 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:33 volumio volumio[1245]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] May 27 17:58:33 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions May 27 17:58:33 volumio volumio[1245]: info: Preparing to save Alsa Options, stopping services first May 27 17:58:33 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 27 17:58:33 volumio volumio[1245]: info: Saving Audio Output to: {"output_device":{"value":"5","label":"USB/BT DAC-1"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} May 27 17:58:33 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:34 volumio volumio[1245]: info: Setting mixer PCM for card USB/BT DAC-1 May 27 17:58:34 volumio vtcs[2211]: [2026-05-27 17:58:34.256] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected May 27 17:58:34 volumio vtcs[2211]: [2026-05-27 17:58:34.256] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 27 17:58:34 volumio volumio[1245]: info: Updating Volume Controller Parameters: Device: 5 Name: USB/BT DAC-1 Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 27 17:58:34 volumio volumio[1245]: info: Disabling external Volume Control May 27 17:58:34 volumio sudo[2302]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:34 volumio sudo[2302]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 17:58:34 volumio volumio[1245]: info: Preparing to generate the ALSA configuration file May 27 17:58:34 volumio systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... May 27 17:58:34 volumio systemd[1]: vtcs.service: Deactivated successfully. May 27 17:58:34 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. May 27 17:58:34 volumio sudo[2302]: pam_unix(sudo:session): session closed for user root May 27 17:58:34 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:58:34 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:34 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:34.631+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:34 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:34.631+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=8407 volume=25 May 27 17:58:34 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:34.631+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:34 volumio sudo[2309]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:34 volumio sudo[2309]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:34 volumio sudo[2309]: pam_unix(sudo:session): session closed for user root May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 27 17:58:34 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 27 17:58:34 volumio volumio[1245]: info: Asound.conf file unchanged, so no further update is needed May 27 17:58:34 volumio volumio[1245]: info: Output device has changed, restarting MPD May 27 17:58:35 volumio volumio[1245]: info: Output device has changed, restarting Shairport Sync May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:35 volumio sudo[2321]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 27 17:58:35 volumio sudo[2321]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:35 volumio volumio[1245]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 27 17:58:35 volumio sudo[2321]: pam_unix(sudo:session): session closed for user root May 27 17:58:35 volumio sudo[2323]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 27 17:58:35 volumio sudo[2323]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:35 volumio sudo[2332]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:35 volumio sudo[2332]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:35 volumio sudo[2333]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:35 volumio sudo[2333]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:35 volumio volumio[1245]: info: MPD Permissions set May 27 17:58:35 volumio systemd[1]: musicservicesshield.service: Deactivated successfully. May 27 17:58:35 volumio systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. May 27 17:58:35 volumio systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... May 27 17:58:35 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... May 27 17:58:35 volumio upmpdcli[1581]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 May 27 17:58:35 volumio systemd[1]: mpd.service: Deactivated successfully. May 27 17:58:35 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. May 27 17:58:35 volumio systemd[1]: mpd.service: Consumed 1.584s CPU time. May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio systemd[1]: mpd.socket: Deactivated successfully. May 27 17:58:35 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 27 17:58:35 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 27 17:58:35 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:35 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:35 volumio systemd[1]: Starting mpd.service - Music Player Daemon... May 27 17:58:35 volumio volumio[1245]: info: Starting Shairport Sync May 27 17:58:35 volumio sudo[2332]: pam_unix(sudo:session): session closed for user root May 27 17:58:35 volumio sudo[2333]: pam_unix(sudo:session): session closed for user root May 27 17:58:35 volumio sudo[2344]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 27 17:58:35 volumio sudo[2344]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:35 volumio sudo[2342]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 27 17:58:35 volumio sudo[2342]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 27 17:58:35 volumio sudo[2342]: pam_unix(sudo:session): session closed for user root May 27 17:58:35 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 27 17:58:35 volumio systemd[1]: shairport-sync.service: Deactivated successfully. May 27 17:58:35 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:35 volumio systemd[1]: shairport-sync.service: Consumed 1.284s CPU time. May 27 17:58:35 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:35 volumio sudo[2344]: pam_unix(sudo:session): session closed for user root May 27 17:58:35 volumio volumio[1245]: info: Shairport-Sync Started May 27 17:58:37 volumio mpd[2349]: 2026-05-27T17:58:37 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 27 17:58:37 volumio systemd[1]: Started mpd.service - Music Player Daemon. May 27 17:58:37 volumio sudo[2323]: pam_unix(sudo:session): session closed for user root May 27 17:58:37 volumio volumio[1245]: error: updateQueue error: null May 27 17:58:37 volumio systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... May 27 17:58:37 volumio upmpdcli[1581]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started May 27 17:58:37 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:37 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:37 volumio bash[2381]: cset: --> shielding system active with May 27 17:58:37 volumio bash[2381]: cset: "system" cpuset of CPUSPEC(1-3) with 170 tasks running May 27 17:58:37 volumio bash[2381]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running May 27 17:58:37 volumio systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. May 27 17:58:37 volumio volumio[1245]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:37 volumio volumio[1245]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:38 volumio sudo[2391]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 27 17:58:38 volumio sudo[2391]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:38 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. May 27 17:58:38 volumio sudo[2391]: pam_unix(sudo:session): session closed for user root May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrieveVolumeLevels May 27 17:58:38 volumio volumio[1245]: info: CoreStateMachine::getcurrentVolume May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume May 27 17:58:38 volumio volumio[1245]: info: Executing endpoint tc_getconfig May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 27 17:58:38 volumio vtcs[2394]: STARTING TidalConnect services, version: 1.6.1 May 27 17:58:38 volumio vtcs[2394]: STARTED TidalConnect services. May 27 17:58:38 volumio volumio[1245]: info: Executing endpoint tc_connect May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 27 17:58:38 volumio volumio[1245]: info: Connecting to TidalConnect May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:38 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:38 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:38 volumio volumio[1245]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received tidalconnect May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:58:38 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:38 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:38 volumio volumio[1245]: info: CONSUME SERVICE: Received update from a service different from the one supposed to be playing music. Skipping notification. Current mpd Received tidalconnect May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.566+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.567+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=12186 volume=25 May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.567+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.568+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=12186 volume=25 May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.568+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.568+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:38 volumio volumio[1245]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.jP75YZbNe2cD6Led7IGckPxfVXv1.548786c1e4765e076bbe9c221ed076fd.state.status' May 27 17:58:38 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:58:38 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:38 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 27 17:58:38 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.736+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.736+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=12530 volume=25 May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.736+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:38 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:38 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:38 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:58:38 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:38 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.967+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.967+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=12788 volume=25 May 27 17:58:38 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:38.967+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:39 volumio volumio[1245]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:39 volumio volumio[1245]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:39 volumio sudo[2423]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 27 17:58:39 volumio sudo[2423]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:39 volumio sudo[2423]: pam_unix(sudo:session): session closed for user root May 27 17:58:41 volumio volumio[1245]: info: TidalConnect service started! May 27 17:58:42 volumio volumio[1245]: info: TidalConnect service started! May 27 17:58:55 volumio volumio[1245]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] May 27 17:58:55 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions May 27 17:58:55 volumio volumio[1245]: info: Preparing to save Alsa Options, stopping services first May 27 17:58:55 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 27 17:58:55 volumio volumio[1245]: info: Saving Audio Output to: {"output_device":{"value":"5","label":"USB/BT DAC-1"},"i2s":false,"i2sid":{"value":"adafruit-max98357","label":"Adafruit MAX98357"}} May 27 17:58:55 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:55 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:55 volumio volumio[1245]: info: Setting mixer PCM for card USB/BT DAC-1 May 27 17:58:55 volumio vtcs[2394]: [2026-05-27 17:58:55.978] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE May 27 17:58:55 volumio vtcs[2394]: [2026-05-27 17:58:55.979] [tisoc] [error] [SpkconServer.cpp:383] recv error. client fd=8 errorno=104 error=Connection reset by peer May 27 17:58:55 volumio vtcs[2394]: [2026-05-27 17:58:55.979] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::volumioUpdateVolumeSettings May 27 17:58:56 volumio volumio[1245]: info: Updating Volume Controller Parameters: Device: 5 Name: USB/BT DAC-1 Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume May 27 17:58:56 volumio volumio[1245]: info: Disabling external Volume Control May 27 17:58:56 volumio sudo[2466]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:56 volumio sudo[2466]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::getUIConfigOnPlugin May 27 17:58:56 volumio volumio[1245]: info: Preparing to generate the ALSA configuration file May 27 17:58:56 volumio systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... May 27 17:58:56 volumio systemd[1]: vtcs.service: Killing process 2400 (vtcs) with signal SIGKILL. May 27 17:58:56 volumio systemd[1]: vtcs.service: Deactivated successfully. May 27 17:58:56 volumio systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. May 27 17:58:56 volumio sudo[2466]: pam_unix(sudo:session): session closed for user root May 27 17:58:56 volumio sudo[2474]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:56 volumio sudo[2474]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:56 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:58:56 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:58:56 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:56.399+09:00 level=WARN msg="received unknown player status" component=volumio status="" May 27 17:58:56 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:56.399+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=30148 volume=25 May 27 17:58:56 volumio volumio5-onboarding[1516]: time=2026-05-27T17:58:56.400+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id= title= May 27 17:58:56 volumio sudo[2474]: pam_unix(sudo:session): session closed for user root May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 27 17:58:56 volumio volumio[1245]: info: Asound.conf file unchanged, so no further update is needed May 27 17:58:56 volumio volumio[1245]: info: Output device has changed, restarting MPD May 27 17:58:56 volumio volumio[1245]: info: Output device has changed, restarting Shairport Sync May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:56 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:56 volumio sudo[2486]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 27 17:58:56 volumio sudo[2486]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:56 volumio sudo[2486]: pam_unix(sudo:session): session closed for user root May 27 17:58:56 volumio volumio[1245]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 27 17:58:56 volumio sudo[2489]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 27 17:58:56 volumio sudo[2489]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:56 volumio volumio[1245]: info: MPD Permissions set May 27 17:58:57 volumio sudo[2497]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:57 volumio sudo[2497]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:57 volumio systemd[1]: musicservicesshield.service: Deactivated successfully. May 27 17:58:57 volumio systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. May 27 17:58:57 volumio systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... May 27 17:58:57 volumio systemd[1]: Stopping mpd.service - Music Player Daemon... May 27 17:58:57 volumio upmpdcli[1581]: :2:../src/mpdcli.cxx:243::MPDCli::eventloop: mpd_run_idle_mask returned 0 May 27 17:58:57 volumio sudo[2494]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 27 17:58:57 volumio sudo[2494]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:57 volumio systemd[1]: mpd.service: Deactivated successfully. May 27 17:58:57 volumio systemd[1]: Stopped mpd.service - Music Player Daemon. May 27 17:58:57 volumio systemd[1]: mpd.service: Consumed 1.376s CPU time. May 27 17:58:57 volumio systemd[1]: mpd.socket: Deactivated successfully. May 27 17:58:57 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket. May 27 17:58:57 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 27 17:58:57 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 27 17:58:57 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. May 27 17:58:57 volumio volumio[1245]: info: Starting Shairport Sync May 27 17:58:57 volumio systemd[1]: Starting mpd.service - Music Player Daemon... May 27 17:58:57 volumio sudo[2497]: pam_unix(sudo:session): session closed for user root May 27 17:58:57 volumio sudo[2494]: pam_unix(sudo:session): session closed for user root May 27 17:58:57 volumio sudo[2508]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 27 17:58:57 volumio sudo[2508]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:58:57 volumio sudo[2506]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 27 17:58:57 volumio sudo[2506]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) May 27 17:58:57 volumio sudo[2506]: pam_unix(sudo:session): session closed for user root May 27 17:58:57 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 27 17:58:57 volumio systemd[1]: shairport-sync.service: Deactivated successfully. May 27 17:58:57 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:57 volumio systemd[1]: shairport-sync.service: Consumed 1.418s CPU time. May 27 17:58:57 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 27 17:58:57 volumio sudo[2508]: pam_unix(sudo:session): session closed for user root May 27 17:58:57 volumio volumio[1245]: info: Shairport-Sync Started May 27 17:58:58 volumio volumio[1245]: info: CoreCommandRouter::volumioGetState May 27 17:58:58 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] May 27 17:58:58 volumio volumio[1245]: info: CoreCommandRouter::volumioPlay May 27 17:58:58 volumio volumio[1245]: info: CoreStateMachine::play index undefined May 27 17:58:58 volumio volumio[1245]: info: CoreStateMachine::setConsumeUpdateService undefined May 27 17:58:58 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:58 volumio volumio[1245]: info: CoreStateMachine::startPlaybackTimer May 27 17:58:58 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:58:58 volumio volumio[1245]: info: [1779872338586] ControllerWebradio::clearAddPlayTrack May 27 17:58:58 volumio volumio[1245]: verbose: ControllerMpd::sendMpdCommand stop May 27 17:58:58 volumio mpd[2513]: 2026-05-27T17:58:58 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 27 17:58:58 volumio systemd[1]: Started mpd.service - Music Player Daemon. May 27 17:58:58 volumio systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set... May 27 17:58:58 volumio sudo[2489]: pam_unix(sudo:session): session closed for user root May 27 17:58:58 volumio volumio[1245]: error: updateQueue error: null May 27 17:58:59 volumio upmpdcli[1581]: :3:../src/mpdcli.cxx:148::MPDCli::startEventLoop: already started May 27 17:58:59 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:59 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:58:59 volumio bash[2545]: cset: --> shielding system active with May 27 17:58:59 volumio bash[2545]: cset: "system" cpuset of CPUSPEC(1-3) with 170 tasks running May 27 17:58:59 volumio bash[2545]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running May 27 17:58:59 volumio systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set. May 27 17:58:59 volumio volumio[1245]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:59 volumio volumio[1245]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 17:58:59 volumio sudo[2556]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 27 17:58:59 volumio sudo[2556]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrieveVolumeLevels May 27 17:59:00 volumio volumio[1245]: info: CoreStateMachine::getcurrentVolume May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume May 27 17:59:00 volumio systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. May 27 17:59:00 volumio sudo[2556]: pam_unix(sudo:session): session closed for user root May 27 17:59:00 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:59:00 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:59:00 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:59:00 volumio volumio[1245]: info: CoreStateMachine::updateTrackBlock May 27 17:59:00 volumio volumio[1245]: info: CorePlayQueue::getTrackBlock May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::volumioRetrievevolume May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.370+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1585 volume=25 May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.370+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id=https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8 title="CBS Music FM" May 27 17:59:00 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:59:00 volumio volumio[1245]: info: Executing endpoint tc_getconfig May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 27 17:59:00 volumio volumio[1245]: info: TidalConnect service stoped! May 27 17:59:00 volumio vtcs[2560]: STARTING TidalConnect services, version: 1.6.1 May 27 17:59:00 volumio vtcs[2560]: STARTED TidalConnect services. May 27 17:59:00 volumio volumio[1245]: info: Executing endpoint tc_connect May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 27 17:59:00 volumio volumio[1245]: info: Connecting to TidalConnect May 27 17:59:00 volumio volumio[1245]: info: VolumeController:: Volume=25 Mute =false May 27 17:59:00 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:59:00 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.581+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1958 volume=25 May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.582+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id=https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8 title="CBS Music FM" May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:59:00 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:59:00 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:59:00 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:59:00 volumio volumio[1245]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::servicePushState May 27 17:59:00 volumio volumio[1245]: info: CoreStateMachine::pushState May 27 17:59:00 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:59:00 volumio volumio[1245]: info: CoreCommandRouter::volumioPushState May 27 17:59:00 volumio volumio[1245]: info: CorePlayQueue::getTrack 0 May 27 17:59:00 volumio volumio[1245]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current webradio Received tidalconnect May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.633+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1958 volume=25 May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.633+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id=https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8 title="CBS Music FM" May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.635+09:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" state=STATUS_STOPPED positionMs=1958 volume=25 May 27 17:59:00 volumio volumio5-onboarding[1516]: time=2026-05-27T17:59:00.635+09:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.0.43:56180,00:00:00:00:00:00%01 @ 0x351fe30" id=https://m-aac.cbs.co.kr/mweb_cbs939/_definst_/cbs939.stream/chunklist.m3u8 title="CBS Music FM" May 27 17:59:00 volumio volumio[1245]: info: Updating tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 27 17:59:00 volumio volumio[1245]: info: Updating tc_connect REST Endpoint for plugin: music_service/tidalconnect May 27 17:59:00 volumio volumio[1245]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 17:59:00 volumio volumio[1245]: Error: ENOENT: no such file or directory, unlink '/tmp/w8D6Ck3Vy2oCOHm9sl1VNI0VjlBkUQjVbO9K7pfOvyNst90QtyUpEMV65IXjT6JMoTFWkIk7fJPli1ixIRlCdruFLj32qlYuX5hV' May 27 17:59:00 volumio volumio[1245]: at Object.unlinkSync (node:fs:1899:3) May 27 17:59:00 volumio volumio[1245]: at ControllerTidalconnect.deleteCertificate (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:11265) May 27 17:59:00 volumio volumio[1245]: at TidalConnectClient. (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:2774) May 27 17:59:00 volumio volumio[1245]: at TidalConnectClient.emit (node:events:514:28) May 27 17:59:00 volumio volumio[1245]: at TidalConnectClient.parseData (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:44713) May 27 17:59:00 volumio volumio[1245]: at /myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:41683 May 27 17:59:00 volumio volumio[1245]: at Array.forEach () May 27 17:59:00 volumio volumio[1245]: at Socket. (/myvolumio/plugins/music_service/tidalconnect/tidalconnect_real:1:41561) May 27 17:59:00 volumio volumio[1245]: at Socket.emit (node:events:514:28) May 27 17:59:00 volumio volumio[1245]: at addChunk (node:internal/streams/readable:343:12) May 27 17:59:00 volumio volumio[1245]: at readableAddChunk (node:internal/streams/readable:316:9) May 27 17:59:00 volumio volumio[1245]: at Readable.push (node:internal/streams/readable:253:10) May 27 17:59:00 volumio volumio[1245]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) { May 27 17:59:00 volumio volumio[1245]: errno: -2, May 27 17:59:00 volumio volumio[1245]: syscall: 'unlink', May 27 17:59:00 volumio volumio[1245]: code: 'ENOENT', May 27 17:59:00 volumio volumio[1245]: path: '/tmp/w8D6Ck3Vy2oCOHm9sl1VNI0VjlBkUQjVbO9K7pfOvyNst90QtyUpEMV65IXjT6JMoTFWkIk7fJPli1ixIRlCdruFLj32qlYuX5hV' May 27 17:59:00 volumio volumio[1245]: } May 27 17:59:00 volumio volumio[1245]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 27 17:59:03 volumio sudo[2611]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-27 17:58' May 27 17:59:03 volumio sudo[2611]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"