Aug 31 15:50:14 volumio-16 ntpd[1150]: CLOCK: time stepped by 62.890845 Aug 31 15:50:14 volumio-16 ntpd[1150]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Aug 31 15:50:18 volumio-16 volumio[1385]: warn: [cd-plugin] cdspeedctl: device or media not ready Aug 31 15:50:18 volumio-16 volumio[1385]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding inputs REST Endpoints Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs Aug 31 15:50:18 volumio-16 volumio[1385]: info: Scanning Audio Inputs Aug 31 15:50:18 volumio-16 volumio[1385]: info: Checking against Known Cards name Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 15:50:18 volumio-16 volumio[1385]: info: [1788205818484] CoreMusicLibrary::Adding element HiFiBerry ADC Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 15:50:18 volumio-16 volumio[1385]: Cannot find translation for source HiFiBerry ADC Aug 31 15:50:18 volumio-16 volumio[1385]: info: Checking against Known Cards name Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 15:50:18 volumio-16 volumio[1385]: info: [1788205818485] CoreMusicLibrary::Adding element Loopback Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 15:50:18 volumio-16 volumio[1385]: Cannot find translation for source HiFiBerry ADC Aug 31 15:50:18 volumio-16 volumio[1385]: Cannot find translation for source Loopback Aug 31 15:50:18 volumio-16 volumio[1385]: info: Checking against Known Cards name Aug 31 15:50:18 volumio-16 volumio[1385]: info: Checking against Known Cards name Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding Server instance for streaming Aug 31 15:50:18 volumio-16 volumio[1385]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio Aug 31 15:50:18 volumio-16 volumio[1385]: error: Hi Res Audio Failed Login: Missing Login Data Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding HIGHRESAUDIO REST API Endpoints Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio Aug 31 15:50:18 volumio-16 volumio[1385]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal Aug 31 15:50:18 volumio-16 volumio[1385]: info: Refreshing TIDAL token Aug 31 15:50:18 volumio-16 volumio[1385]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz Aug 31 15:50:18 volumio-16 volumio[1385]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect Aug 31 15:50:18 volumio-16 volumio[1385]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect Aug 31 15:50:18 volumio-16 sudo[2345]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 31 15:50:18 volumio-16 sudo[2345]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 volumio[1385]: info: QobuzConnect: Starting Qobuz Connect socket and service Aug 31 15:50:18 volumio-16 sudo[2352]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 31 15:50:18 volumio-16 sudo[2352]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 sudo[2345]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 volumio[1385]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections Aug 31 15:50:18 volumio-16 volumio[1385]: info: Stopping AccessToken refresher cron for QOBUZ Aug 31 15:50:18 volumio-16 sudo[2352]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 sudo[2355]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 31 15:50:18 volumio-16 sudo[2355]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 volumio[1385]: info: AccessToken refresher cron started for QOBUZ Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding QOBUZ REST API Endpoints Aug 31 15:50:18 volumio-16 volumio[1385]: info: Updating MyVolumio device info Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: Updating MyVolumio device info Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Getting audio outputs on start Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Requesting all other devices output Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Adding multiroomSync output Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding audio output: Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:18 volumio-16 volumio[1385]: info: Successfully Added MyVolumio device Aug 31 15:50:18 volumio-16 volumio[1385]: info: Successfully Added MyVolumio device Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Aug 31 15:50:18 volumio-16 volumio[1385]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on Aug 31 15:50:18 volumio-16 volumio[1385]: info: MPD Permissions set Aug 31 15:50:18 volumio-16 sudo[2359]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Aug 31 15:50:18 volumio-16 sudo[2359]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Aug 31 15:50:18 volumio-16 sudo[2355]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 sudo[2359]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumiobt[2367]: INFO [BTSTART] Ensuring Bluetooth directory exists... Aug 31 15:50:18 volumio-16 sudo[2371]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth Aug 31 15:50:18 volumio-16 sudo[2371]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 sudo[2371]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 volumio[1385]: error: updateQueue error: null Aug 31 15:50:18 volumio-16 sudo[2375]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth Aug 31 15:50:18 volumio-16 sudo[2375]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 sudo[2375]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 volumiobt[2377]: INFO [BTSTART] Powering on Bluetooth if needed... Aug 31 15:50:18 volumio-16 bluetoothd[961]: Adv Monitor app :1.28 disconnected from D-Bus Aug 31 15:50:18 volumio-16 volumiobt[2380]: INFO [BTSTART] Making Bluetooth discoverable and pairable... Aug 31 15:50:18 volumio-16 volumio[1385]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully Aug 31 15:50:18 volumio-16 volumio[1385]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart Aug 31 15:50:18 volumio-16 sudo[2383]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Aug 31 15:50:18 volumio-16 sudo[2383]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 volumiobt[2382]: [198B blob data] Aug 31 15:50:18 volumio-16 volumiobt[2382]: [162B blob data] Aug 31 15:50:18 volumio-16 volumiobt[2382]: [162B blob data] Aug 31 15:50:18 volumio-16 volumiobt[2382]: [162B blob data] Aug 31 15:50:18 volumio-16 volumiobt[2382]: [118B blob data] Aug 31 15:50:18 volumio-16 volumiobt[2382]: [77-BC-54-C2-C3-92]> discoverable on Aug 31 15:50:18 volumio-16 volumiobt[2382]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended Aug 31 15:50:18 volumio-16 volumiobt[2382]: [77-BC-54-C2-C3-92]> pairable on Aug 31 15:50:18 volumio-16 volumio[1385]: info: Executing endpoint qc_getconfig Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 31 15:50:18 volumio-16 bluetoothd[961]: Path / reserved for Adv Monitor app :1.30 Aug 31 15:50:18 volumio-16 systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 31 15:50:18 volumio-16 systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Aug 31 15:50:18 volumio-16 bluetoothd[961]: Adv Monitor app :1.30 disconnected from D-Bus Aug 31 15:50:18 volumio-16 volumiobt[2382]: [77-BC-54-C2-C3-92]> Aug 31 15:50:18 volumio-16 volumiobt[2390]: INFO [BTSTART] Registering Bluetooth agent... Aug 31 15:50:18 volumio-16 volumio[1385]: info: Starting Shairport Sync Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.701 [2357.2357] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Aug 31 15:50:18 volumio-16 systemd[1]: Started sshtunnel.service - MyVolumio SSH Tunnel. Aug 31 15:50:18 volumio-16 volumiobt[2391]: [NEW] Media /org/bluez/hci0 Aug 31 15:50:18 volumio-16 volumiobt[2391]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 31 15:50:18 volumio-16 volumiobt[2391]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 31 15:50:18 volumio-16 volumiobt[2391]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 31 15:50:18 volumio-16 sudo[2393]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 15:50:18 volumio-16 sudo[2393]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 bluetoothd[961]: Path / reserved for Adv Monitor app :1.31 Aug 31 15:50:18 volumio-16 sudo[2383]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 bluetoothd[961]: Adv Monitor app :1.31 disconnected from D-Bus Aug 31 15:50:18 volumio-16 volumio[1385]: info: Preparing to generate the ALSA configuration file Aug 31 15:50:18 volumio-16 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 15:50:18 volumio-16 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 15:50:18 volumio-16 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:50:18 volumio-16 systemd[1]: shairport-sync.service: Consumed 1.530s CPU time. Aug 31 15:50:18 volumio-16 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:50:18 volumio-16 autossh[2395]: port set to 0, monitoring disabled Aug 31 15:50:18 volumio-16 autossh[2395]: starting ssh (count 1) Aug 31 15:50:18 volumio-16 sudo[2393]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 autossh[2395]: ssh child pid is 2402 Aug 31 15:50:18 volumio-16 volumiobt[2398]: No agent is registered Aug 31 15:50:18 volumio-16 volumiobt[2398]: [NEW] Media /org/bluez/hci0 Aug 31 15:50:18 volumio-16 volumiobt[2398]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 31 15:50:18 volumio-16 volumiobt[2398]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 31 15:50:18 volumio-16 volumiobt[2398]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 31 15:50:18 volumio-16 bluetoothd[961]: Path / reserved for Adv Monitor app :1.33 Aug 31 15:50:18 volumio-16 bluetoothd[961]: Adv Monitor app :1.33 disconnected from D-Bus Aug 31 15:50:18 volumio-16 volumio[1385]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Aug 31 15:50:18 volumio-16 volumio[1385]: info: QobuzConnect: QOBUZ Connect daemon connected Aug 31 15:50:18 volumio-16 volumiobt[2403]: INFO [BTSTART] Agent registered successfully. Aug 31 15:50:18 volumio-16 volumio[1385]: info: Remote SSH Started Aug 31 15:50:18 volumio-16 volumiobt[2406]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.758 [2357.2357] INFO VolumeManager: [0x21bc260]: Setting new playback volume: 75 Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.758 [2357.2357] INFO VolumeManager: [0x21bc260]: Setting new mute state: 0 Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.758 [2357.2357] INFO AudioStreamManager: [0x21bbfb8]: Setting new audio download buffer size: 1048576 Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.759 [2357.2357] INFO QobuzConnect: [0x21bcb28]: Client initialized! Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.759 [2357.2357] INFO SampleApp: Starting Avahi advertising, name: Volumio 16, service name: _qobuz-connect._tcp Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.768 [2357.2357] INFO LocalConfigManager: [0x21bbce0]: Starting Local Configuration server Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.768 [2357.2357] INFO SampleApp: Starting Local configuration server Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.768 [2357.2357] INFO SampleApp: Connected to UNIX socket client 0x21a6818 Aug 31 15:50:18 volumio-16 volumio[1385]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Aug 31 15:50:18 volumio-16 volumio[1385]: info: Reading ALSA contributions from plugins. Aug 31 15:50:18 volumio-16 volumio[1385]: info: Successfully Updated MyVolumio device Aug 31 15:50:18 volumio-16 volumiossh-tunnel[2402]: Warning: Permanently added '[us3.myvolumio.org]:2222' (RSA) to the list of known hosts. Aug 31 15:50:18 volumio-16 volumio[1385]: info: Shairport-Sync Started Aug 31 15:50:18 volumio-16 volumio[1385]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 22 Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Found cast device: OLED65G5SUB.DCCQLJR-7fbb658c124b11f8a5faa551f664a250 Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding audio output: Aug 31 15:50:18 volumio-16 volumio[1385]: info: Successfully Updated MyVolumio device Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.851 [2357.2357] INFO SampleApp: Playback volume changed: 75 Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:18 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:18 volumio-16 volumio[1385]: info: Asound.conf file written Aug 31 15:50:18 volumio-16 sudo[2425]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 31 15:50:18 volumio-16 sudo[2425]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 sudo[2425]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 31 15:50:18 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 31 15:50:18 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 31 15:50:18 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Aug 31 15:50:18 volumio-16 volumio[1385]: info: Output device has changed, restarting MPD Aug 31 15:50:18 volumio-16 volumio[1385]: info: Output device has changed, restarting Shairport Sync Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:18 volumio-16 sudo[2431]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 15:50:18 volumio-16 sudo[2433]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 15:50:18 volumio-16 sudo[2431]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 sudo[2431]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 volumio[1385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:18 volumio-16 sudo[2433]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 volumio[1385]: info: QobuzConnect: setDeactiveState invoked Aug 31 15:50:18 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:18 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:18 volumio-16 volumio[1385]: info: Preparing to generate the ALSA configuration file Aug 31 15:50:18 volumio-16 systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 31 15:50:18 volumio-16 sudo[2447]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 31 15:50:18 volumio-16 sudo[2447]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Found cast device: SHIELD-Android-TV-57fca0349ba0f255b7bee3171e51b675 Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding audio output: Aug 31 15:50:18 volumio-16 sudo[2447]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:18 volumio-16 systemd[1]: mpd.service: Deactivated successfully. Aug 31 15:50:18 volumio-16 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 15:50:18 volumio-16 systemd[1]: mpd.socket: Deactivated successfully. Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Found cast device: SHIELD-Android-TV-6965c7b065dedc48b280ed631e252466 Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding audio output: Aug 31 15:50:18 volumio-16 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 15:50:18 volumio-16 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 15:50:18 volumio-16 volumio[1385]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 31 15:50:18 volumio-16 volumio[1385]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Aug 31 15:50:18 volumio-16 volumio[1385]: info: Reading ALSA contributions from plugins. Aug 31 15:50:18 volumio-16 volumio[1385]: info: MRS: Found cast device: SHIELD-Android-TV-31db48d35baf3c85f6537256ce24f303 Aug 31 15:50:18 volumio-16 volumio[1385]: info: Adding audio output: Aug 31 15:50:18 volumio-16 sudo[2449]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 31 15:50:18 volumio-16 sudo[2449]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:18 volumio-16 volumio[1385]: info: Access Token successfully retrieved Aug 31 15:50:18 volumio-16 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 15:50:18 volumio-16 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 15:50:18 volumio-16 volumio[1385]: info: MPD Permissions set Aug 31 15:50:18 volumio-16 systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Aug 31 15:50:18 volumio-16 qobuz-connect[2357]: 20260831 15:50:18.997 [2357.2357] INFO SampleApp: Stopping Local configuration server Aug 31 15:50:19 volumio-16 sudo[2452]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 15:50:19 volumio-16 sudo[2452]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] Connecting to system D-Bus Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] Connected to system D-Bus Aug 31 15:50:19 volumio-16 sudo[2452]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 bluezutils [INFO] Found adapter at: /org/bluez/hci0 Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] Found Bluetooth adapter: /org/bluez/hci0 Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] Set DiscoverableTimeout to infinite Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] Enabled Discoverable mode Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] Agent registered at /local/a2dpagent Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] Agent set as default Aug 31 15:50:19 volumio-16 volumiobt[2417]: 2026-08-31 15:50:19 a2dp-agent [INFO] A2DP agent running, waiting for connections... Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:19 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:19 volumio-16 volumio[1385]: info: Starting Shairport Sync Aug 31 15:50:19 volumio-16 volumio[1385]: info: Asound.conf file written Aug 31 15:50:19 volumio-16 sudo[2461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 15:50:19 volumio-16 sudo[2461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:19 volumio-16 sudo[2464]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 31 15:50:19 volumio-16 sudo[2464]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:19 volumio-16 sudo[2464]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 15:50:19 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 31 15:50:19 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 31 15:50:19 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 31 15:50:19 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Aug 31 15:50:19 volumio-16 volumio[1385]: info: Output device has changed, restarting MPD Aug 31 15:50:19 volumio-16 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 15:50:19 volumio-16 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:50:19 volumio-16 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:50:19 volumio-16 volumio[1385]: info: Output device has changed, restarting Shairport Sync Aug 31 15:50:19 volumio-16 sudo[2471]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 15:50:19 volumio-16 sudo[2461]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 sudo[2471]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:19 volumio-16 sudo[2474]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 15:50:19 volumio-16 sudo[2474]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:19 volumio-16 sudo[2471]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 volumio[1385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 15:50:19 volumio-16 volumio[1385]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 systemd[1]: mpd.service: Deactivated successfully. Aug 31 15:50:19 volumio-16 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 15:50:19 volumio-16 systemd[1]: mpd.socket: Deactivated successfully. Aug 31 15:50:19 volumio-16 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 15:50:19 volumio-16 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 15:50:19 volumio-16 volumio[1385]: info: QobuzConnect: setDeactiveState invoked Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:19 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:19 volumio-16 volumio[1385]: info: Successfully retrieved User Session From TIDAL Aug 31 15:50:19 volumio-16 volumio[1385]: info: MPD Permissions set Aug 31 15:50:19 volumio-16 volumio[1385]: info: Shairport-Sync Started Aug 31 15:50:19 volumio-16 sudo[2503]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 31 15:50:19 volumio-16 sudo[2503]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 15:50:19 volumio-16 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:19 volumio-16 volumio[1385]: info: Starting Shairport Sync Aug 31 15:50:19 volumio-16 sudo[2503]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 sudo[2512]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 15:50:19 volumio-16 sudo[2512]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:19 volumio-16 sudo[2513]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 31 15:50:19 volumio-16 sudo[2513]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:19 volumio-16 volumio[1385]: info: Successfully retrieved User Subscription From TIDAL Aug 31 15:50:19 volumio-16 volumio[1385]: info: Adding TIDAL to Browse Sources Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Aug 31 15:50:19 volumio-16 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 15:50:19 volumio-16 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 15:50:19 volumio-16 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:50:19 volumio-16 volumio[1385]: info: [1788205819206] CoreMusicLibrary::Adding element TIDAL Aug 31 15:50:19 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 15:50:19 volumio-16 volumio[1385]: Cannot find translation for source HiFiBerry ADC Aug 31 15:50:19 volumio-16 volumio[1385]: Cannot find translation for source Loopback Aug 31 15:50:19 volumio-16 sudo[2507]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 15:50:19 volumio-16 sudo[2507]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 15:50:19 volumio-16 volumio[1385]: Cannot find translation for source TIDAL Aug 31 15:50:19 volumio-16 volumio[1385]: info: Adding TIDAL REST API Endpoints Aug 31 15:50:19 volumio-16 sudo[2507]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:50:19 volumio-16 sudo[2512]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 volumio[1385]: info: Shairport-Sync Started Aug 31 15:50:19 volumio-16 mpd[2518]: 2026-08-31T15:50:19 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 31 15:50:19 volumio-16 systemd[1]: Started mpd.service - Music Player Daemon. Aug 31 15:50:19 volumio-16 sudo[2474]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 sudo[2433]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:19 volumio-16 volumio[1385]: error: MPD error: The expression evaluated to a falsy value: Aug 31 15:50:19 volumio-16 volumio[1385]: assert.ok(self.idling) Aug 31 15:50:19 volumio-16 volumio[1385]: error: The expression evaluated to a falsy value: Aug 31 15:50:19 volumio-16 volumio[1385]: assert.ok(self.idling) Aug 31 15:50:19 volumio-16 volumio[1385]: error: updateQueue error: null Aug 31 15:50:20 volumio-16 qobuz-connect[2357]: 20260831 15:50:20.779 [2357.2357] INFO SampleApp: shat down connection on UNIX socket Aug 31 15:50:20 volumio-16 volumio[1385]: info: QobuzConnect: Qobuz Connect client [object Object] disconnected Aug 31 15:50:20 volumio-16 volumio[1385]: info: QobuzConnect: setDeactiveState invoked Aug 31 15:50:20 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:20 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:20 volumio-16 systemd[1]: qobuz-connect.service: Deactivated successfully. Aug 31 15:50:20 volumio-16 systemd[1]: Stopped qobuz-connect.service - Volumio Qobuz Connect Service. Aug 31 15:50:20 volumio-16 systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. Aug 31 15:50:20 volumio-16 sudo[2513]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:20 volumio-16 sudo[2449]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:20 volumio-16 volumio[1385]: info: Executing endpoint qc_getconfig Aug 31 15:50:20 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.827 [2549.2549] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.828 [2549.2549] INFO VolumeManager: [0x2801260]: Setting new playback volume: 75 Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.828 [2549.2549] INFO VolumeManager: [0x2801260]: Setting new mute state: 0 Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.828 [2549.2549] INFO AudioStreamManager: [0x2800fb8]: Setting new audio download buffer size: 1048576 Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.828 [2549.2549] INFO QobuzConnect: [0x2801b28]: Client initialized! Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.828 [2549.2549] INFO SampleApp: Starting Avahi advertising, name: Volumio 16, service name: _qobuz-connect._tcp Aug 31 15:50:20 volumio-16 volumio[1385]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] Aug 31 15:50:20 volumio-16 volumio[1385]: info: QobuzConnect: QOBUZ Connect daemon connected Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.832 [2549.2549] INFO LocalConfigManager: [0x2800ce0]: Starting Local Configuration server Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.832 [2549.2549] INFO SampleApp: Starting Local configuration server Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.832 [2549.2549] INFO SampleApp: Connected to UNIX socket client 0x27eb818 Aug 31 15:50:20 volumio-16 qobuz-connect[2549]: 20260831 15:50:20.977 [2549.2549] INFO SampleApp: Playback volume changed: 75 Aug 31 15:50:20 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:20 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:21 volumio-16 volumio[1385]: info: TidalConnect service stoped! Aug 31 15:50:21 volumio-16 volumio[1385]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 31 15:50:21 volumio-16 volumio[1385]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 31 15:50:21 volumio-16 sudo[2564]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 31 15:50:21 volumio-16 sudo[2564]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:21 volumio-16 systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. Aug 31 15:50:21 volumio-16 sudo[2564]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:21 volumio-16 volumio[1385]: info: Executing endpoint tc_getconfig Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Aug 31 15:50:21 volumio-16 vtcs[2567]: STARTING TidalConnect services, version: 1.6.1 Aug 31 15:50:21 volumio-16 vtcs[2567]: STARTED TidalConnect services. Aug 31 15:50:21 volumio-16 volumio[1385]: info: Executing endpoint tc_connect Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Aug 31 15:50:21 volumio-16 volumio[1385]: info: Connecting to TidalConnect Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:21 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:21 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:21 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:21 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:21 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:21 volumio-16 volumio[1385]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received tidalconnect Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:21 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:21 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:21 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:21 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:21 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:21 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:21 volumio-16 volumio[1385]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received tidalconnect Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.681-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.682-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.682-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.682-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.683-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.684-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.684-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:21 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:21.684-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:21 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status stop Aug 31 15:50:21 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status stop Aug 31 15:50:21 volumio-16 sudo[2584]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:50:21 volumio-16 sudo[2584]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:21 volumio-16 sudo[2586]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:50:21 volumio-16 sudo[2586]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:21 volumio-16 sudo[2586]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:21 volumio-16 sudo[2584]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:21 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:50:21 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:50:23 volumio-16 systemd[1]: systemd-fsckd.service: Deactivated successfully. Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPlay Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::play index undefined Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:50:23 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::startPlaybackTimer Aug 31 15:50:23 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:23 volumio-16 volumio[1385]: info: [1788205823391] ControllerTidal::clearAddPlayTrack Aug 31 15:50:23 volumio-16 volumio[1385]: info: Getting stream with soundQuality HI_RES Aug 31 15:50:23 volumio-16 volumio[1385]: info: getStreamUrl took 160 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand stop took 1 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand clear Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:50:23 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand clear took 1 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==" Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:50:23 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:50:23 volumio-16 volumio[1385]: error: updateQueue error: null Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:50:23 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 2ms Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==" took 1 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 1ms Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand play Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:50:23 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 1ms Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand play took 0 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 0ms Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand status took 24 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand status took 24 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:23 volumio-16 volumio[1385]: info: Aug 31 15:50:23 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand status took 1 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand status took 0 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"922 Kbps","isStreaming":false,"title":"0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","trackType":"tidal"} Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus stop Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1100,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"909 Kbps","isStreaming":false,"title":"0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","trackType":"tidal"} Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:50:23 volumio-16 volumio[1385]: info: Received an update from plugin. extracting info from payload Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 34ms Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.627-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.627-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.627-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.628-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.628-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.628-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.628-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.628-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 48ms Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 23 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 23 milliseconds Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1100,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"977 Kbps","isStreaming":false,"title":"0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","trackType":"tidal"} Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:50:23 volumio-16 volumio[1385]: info: Received an update from plugin. extracting info from payload Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:23 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1100,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"977 Kbps","isStreaming":false,"title":"0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","trackType":"tidal"} Aug 31 15:50:23 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:50:23 volumio-16 volumio[1385]: info: Received an update from plugin. extracting info from payload Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:23 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:23 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.662-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.662-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.662-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.662-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.663-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.663-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.663-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.663-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.665-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.665-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.665-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.666-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.666-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.666-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.666-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:23.666-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 73ms Aug 31 15:50:23 volumio-16 volumio[1385]: info: ------------------------------ 72ms Aug 31 15:50:23 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:23 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:23 volumio-16 sudo[2596]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:23 volumio-16 sudo[2596]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:23 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:23 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:23 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:23 volumio-16 sudo[2599]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:23 volumio-16 sudo[2599]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:23 volumio-16 sudo[2601]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:23 volumio-16 sudo[2601]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:23 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:23 volumio-16 sudo[2603]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:23 volumio-16 sudo[2603]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:23 volumio-16 sudo[2607]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:23 volumio-16 sudo[2607]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:23 volumio-16 sudo[2611]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:23 volumio-16 sudo[2611]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:23 volumio-16 systemd[1]: Started peppymeterbasic.service - peppymeterbasic Daemon. Aug 31 15:50:23 volumio-16 sudo[2596]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:23 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:23 volumio-16 sudo[2603]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:23 volumio-16 sudo[2607]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:23 volumio-16 sudo[2601]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:23 volumio-16 sudo[2611]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:23 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:23 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:23 volumio-16 sudo[2599]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:23 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:23 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:23 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:24 volumio-16 kernel: dma dma2chan2: dma2chan2 failed to stop Aug 31 15:50:24 volumio-16 volumio[1385]: info: Aug 31 15:50:24 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:24 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:24 volumio-16 volumio[1385]: info: Aug 31 15:50:24 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:24 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:24 volumio-16 volumio[1385]: error: MPD returned error for command status: Failed to open audio output Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand clearerror Aug 31 15:50:24 volumio-16 volumio[1385]: info: sendMpdCommand status took 5 milliseconds Aug 31 15:50:24 volumio-16 volumio[1385]: error: MPD returned error for command status: Failed to open audio output Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand clearerror Aug 31 15:50:24 volumio-16 volumio[1385]: info: sendMpdCommand status took 6 milliseconds Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:24 volumio-16 volumio[1385]: info: sendMpdCommand clearerror took 4 milliseconds Aug 31 15:50:24 volumio-16 volumio[1385]: info: sendMpdCommand clearerror took 4 milliseconds Aug 31 15:50:24 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 3 milliseconds Aug 31 15:50:24 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 2 milliseconds Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:24 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":3049,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"827 Kbps","isStreaming":false,"title":"0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","trackType":"tidal"} Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService pause Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:24 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::stPlaybackTimer Aug 31 15:50:24 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":3049,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"827 Kbps","isStreaming":false,"title":"0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209423~OWExY2E5NzkwOGNmMWIwOGI5OTZmZTU3MDhiYjEzYTUyZWIyNDFiYQ==","trackType":"tidal"} Aug 31 15:50:24 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService pause Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:24 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:24 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreStateMachine::stPlaybackTimer Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.290-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PAUSED positionMs=863 volume=100 Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.291-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PAUSED positionMs=863 volume=100 Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.294-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PAUSED positionMs=863 volume=100 Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.295-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PAUSED positionMs=863 volume=100 Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.295-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.295-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.295-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:24 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:24.295-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:24 volumio-16 volumio[1385]: info: ------------------------------ 36ms Aug 31 15:50:24 volumio-16 volumio[1385]: info: ------------------------------ 35ms Aug 31 15:50:24 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status pause Aug 31 15:50:24 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status pause Aug 31 15:50:24 volumio-16 sudo[2619]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:50:24 volumio-16 sudo[2619]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:24 volumio-16 sudo[2617]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:50:24 volumio-16 sudo[2617]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:24 volumio-16 volumio[1385]: info: touch_display: Setting screensaver timeout to 0 seconds. Aug 31 15:50:24 volumio-16 systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon... Aug 31 15:50:24 volumio-16 systemd[1]: peppymeterbasic.service: Deactivated successfully. Aug 31 15:50:24 volumio-16 systemd[1]: Stopped peppymeterbasic.service - peppymeterbasic Daemon. Aug 31 15:50:24 volumio-16 sudo[2619]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:24 volumio-16 sudo[2617]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:24 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:50:24 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:50:24 volumio-16 systemd[1]: systemd-hostnamed.service: Deactivated successfully. Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 15:50:24 volumio-16 volumio[1385]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 31 15:50:24 volumio-16 volumio[1385]: info: Received Get System Version Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 15:50:24 volumio-16 volumio[1385]: info: Received Get System Info Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 31 15:50:24 volumio-16 volumio[1385]: info: Discovery: Getting this device information Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 31 15:50:24 volumio-16 volumio[1385]: info: TidalConnect service started! Aug 31 15:50:24 volumio-16 volumio[1385]: [Metrics] CommandRouter: 24s 991.40ms Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::volumiosetStartupVolume Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::Close All Modals sent Aug 31 15:50:24 volumio-16 volumio[1385]: info: CoreCommandRouter::Close All Modals sent Aug 31 15:50:24 volumio-16 kernel: dma dma2chan2: dma2chan2 is non-idle! Aug 31 15:50:24 volumio-16 systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Aug 31 15:50:24 volumio-16 systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 15:50:24 volumio-16 systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Aug 31 15:50:24 volumio-16 sudo[2216]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:24 volumio-16 volumio[1385]: info: Upmpdcli Daemon Started Aug 31 15:50:25 volumio-16 volumio[1385]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Aug 31 15:50:25 volumio-16 volumio[1385]: Playing WAVE '/volumio/app/startup.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo Aug 31 15:50:25 volumio-16 volumio[1385]: ALSA lib ./src/pcm_volumioswitch.c:912:(_snd_pcm_volumioswitch_advance) PCM volumioMultiRoomServer cannot write to target PCM peppy_in as it has failed its update check. Aug 31 15:50:25 volumio-16 volumio[1385]: underrun!!! (at least 600.032 ms long) Aug 31 15:50:25 volumio-16 volumio[1385]: aplay: xrun:1672: xrun: prepare error: Device or resource busy Aug 31 15:50:25 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 31 15:50:25 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 15:50:25 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 31 15:50:26 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 31 15:50:26 volumio-16 volumio[1385]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 23 Aug 31 15:50:26 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Aug 31 15:50:31 volumio-16 volumio[1385]: info: BOOT COMPLETED Aug 31 15:50:31 volumio-16 volumio-remote-updater[1006]: Test mode disabled Aug 31 15:50:31 volumio-16 volumio-remote-updater[1006]: Alpha mode disabled Aug 31 15:50:31 volumio-16 volumio-remote-updater[1006]: Alpha legacy test mode disabled Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetBrowseSources Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 31 15:50:31 volumio-16 volumio[1385]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Aug 31 15:50:31 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Aug 31 15:50:33 volumio-16 upmpdcli[2665]: writing RSA key Aug 31 15:50:35 volumio-16 volumio[1385]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object] Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions Aug 31 15:50:35 volumio-16 sudo[2682]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 15:50:35 volumio-16 sudo[2682]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:35 volumio-16 sudo[2682]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:35 volumio-16 sudo[2684]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 15:50:35 volumio-16 sudo[2684]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:35 volumio-16 volumio[1385]: info: MPD Permissions set Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:50:35 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:50:35 volumio-16 systemd[1]: mpd.service: Deactivated successfully. Aug 31 15:50:35 volumio-16 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 15:50:35 volumio-16 systemd[1]: mpd.socket: Deactivated successfully. Aug 31 15:50:35 volumio-16 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 15:50:35 volumio-16 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 15:50:35 volumio-16 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 15:50:35 volumio-16 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 15:50:35 volumio-16 sudo[2693]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 15:50:35 volumio-16 sudo[2693]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 15:50:35 volumio-16 sudo[2693]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:36 volumio-16 mpd[2695]: 2026-08-31T15:50:36 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 31 15:50:36 volumio-16 systemd[1]: Started mpd.service - Music Player Daemon. Aug 31 15:50:36 volumio-16 sudo[2684]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:36 volumio-16 volumio[1385]: error: updateQueue error: null Aug 31 15:50:42 volumio-16 volumio[1385]: info: Preload queue cleared Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::ClearQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::stop Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::stPlaybackTimer Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::updateTrackBlock Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::getTrackBlock Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:42 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:42 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::serviceStop Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::serviceStop Aug 31 15:50:42 volumio-16 volumio[1385]: info: [1788205842306] ControllerTidal::stop Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 31 15:50:42 volumio-16 volumio[1385]: info: ControllerMpd::stop Aug 31 15:50:42 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::clearPlayQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::saveQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::addQueueItems Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::addQueueItems Aug 31 15:50:42 volumio-16 volumio[1385]: info: Preload queue cleared Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/508246122 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/508246122 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/468464725 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/468464725 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/423507028 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/423507028 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/452020582 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/452020582 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/444099445 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/444099445 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/489200570 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/489200570 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/514275908 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/514275908 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/499884584 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/499884584 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/489200575 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/489200575 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/71266982 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/71266982 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/454025173 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/454025173 in service tidal Aug 31 15:50:42 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:42.315-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:50:42 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:42.315-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:50:42 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:42.315-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:42 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:42.315-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:42 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status stop Aug 31 15:50:42 volumio-16 sudo[2716]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:50:42 volumio-16 sudo[2716]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:42 volumio-16 volumio[1385]: info: sendMpdCommand stop took 85 milliseconds Aug 31 15:50:42 volumio-16 systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service... Aug 31 15:50:42 volumio-16 sudo[2716]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:42 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 252 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 253 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 255 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 257 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 269 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 265 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 260 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 262 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 272 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 296 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 330 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: error: TIDAL Browse Error: failed to get track: got 404: {"status":404,"subStatus":2001,"userMessage":"Track [71266982] not found"} Aug 31 15:50:42 volumio-16 volumio[1385]: error: Commandrouter: Cannot explode uri tidal://song/71266982 from service tidal: failed to get track: got 404: {"status":404,"subStatus":2001,"userMessage":"Track [71266982] not found"} Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::saveQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::updateTrackBlock Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::getTrackBlock Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPlay Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::play index 10 Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::addQueueItems Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::addQueueItems Aug 31 15:50:42 volumio-16 volumio[1385]: info: Preload queue cleared Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/458042479 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/458042479 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/461783067 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/461783067 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/472580872 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/472580872 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/456432807 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/456432807 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/523120820 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/523120820 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/534763546 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/534763546 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/492071299 Aug 31 15:50:42 volumio-16 volumio[1385]: info: Exploding uri tidal://song/492071299 in service tidal Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::stop Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::play index undefined Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 10 Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 54 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 56 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 56 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 56 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 57 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 57 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: explodeTIDALUri took 59 milliseconds Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::saveQueue Aug 31 15:50:42 volumio-16 volumio[1385]: info: CoreStateMachine::updateTrackBlock Aug 31 15:50:42 volumio-16 volumio[1385]: info: CorePlayQueue::getTrackBlock Aug 31 15:50:43 volumio-16 systemd[1]: setdatetime-helper.service: Deactivated successfully. Aug 31 15:50:43 volumio-16 systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPlay Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::play index undefined Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:50:48 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::startPlaybackTimer Aug 31 15:50:48 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:48 volumio-16 volumio[1385]: info: [1788205848380] ControllerTidal::clearAddPlayTrack Aug 31 15:50:48 volumio-16 volumio[1385]: info: Getting stream with soundQuality HI_RES Aug 31 15:50:48 volumio-16 volumio[1385]: info: getStreamUrl took 242 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand stop took 0 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand clear Aug 31 15:50:48 volumio-16 volumio[1385]: info: Aug 31 15:50:48 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:50:48 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand clear took 1 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==" Aug 31 15:50:48 volumio-16 volumio[1385]: error: updateQueue error: null Aug 31 15:50:48 volumio-16 volumio[1385]: info: Aug 31 15:50:48 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:50:48 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:50:48 volumio-16 volumio[1385]: info: ------------------------------ 1ms Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==" took 1 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand play Aug 31 15:50:48 volumio-16 volumio[1385]: info: ------------------------------ 1ms Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand play took 1 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: info: Aug 31 15:50:48 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:48 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:48 volumio-16 volumio[1385]: info: Aug 31 15:50:48 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand status took 27 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand status took 1 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:48 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==","trackType":"tidal"} Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus stop Aug 31 15:50:48 volumio-16 volumio[1385]: info: ------------------------------ 30ms Aug 31 15:50:48 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 2 milliseconds Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:48 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1100,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"977 Kbps","isStreaming":false,"title":"0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==","trackType":"tidal"} Aug 31 15:50:48 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:50:48 volumio-16 volumio[1385]: info: Received an update from plugin. extracting info from payload Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:48 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:48 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:48 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:48 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.690-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.690-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.690-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.690-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.691-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.691-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=0 volume=100 Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.692-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:48 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:48.692-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:48 volumio-16 volumio[1385]: info: ------------------------------ 38ms Aug 31 15:50:48 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:48 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:50:48 volumio-16 sudo[2750]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:48 volumio-16 sudo[2750]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:48 volumio-16 sudo[2752]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:50:48 volumio-16 sudo[2752]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:48 volumio-16 systemd[1]: Started peppymeterbasic.service - peppymeterbasic Daemon. Aug 31 15:50:48 volumio-16 sudo[2750]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:48 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:48 volumio-16 sudo[2752]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:48 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:50:49 volumio-16 kernel: dma dma2chan2: dma2chan2 failed to stop Aug 31 15:50:49 volumio-16 volumio[1385]: info: Aug 31 15:50:49 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:50:49 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:50:49 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:50:49 volumio-16 volumio[1385]: error: MPD returned error for command status: Failed to open audio output Aug 31 15:50:49 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand clearerror Aug 31 15:50:49 volumio-16 volumio[1385]: info: sendMpdCommand status took 3 milliseconds Aug 31 15:50:49 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:50:49 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:50:49 volumio-16 volumio[1385]: info: sendMpdCommand clearerror took 6 milliseconds Aug 31 15:50:49 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 31 15:50:49 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:50:49 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:50:49 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:50:49 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":3049,"duration":210,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"827 Kbps","isStreaming":false,"title":"0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiRkMzhmMzhiMWYyYjM4Y2MzMDZlZDg3NmVkZjE3Mjk3OC5tcDQ/0.flac?token=1788209448~NzYwYWI5MzVlODkxMmRhODNkZWQ5ZTM2MGU5NDgwYTcwYjA0NjdmMw==","trackType":"tidal"} Aug 31 15:50:49 volumio-16 volumio[1385]: verbose: CURRENT POSITION 0 Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService pause Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:50:49 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:50:49 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:50:49 volumio-16 volumio[1385]: info: CoreStateMachine::stPlaybackTimer Aug 31 15:50:49 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:49.347-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PAUSED positionMs=500 volume=100 Aug 31 15:50:49 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:49.347-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PAUSED positionMs=500 volume=100 Aug 31 15:50:49 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:49.347-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:49 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:50:49.347-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:50:49 volumio-16 volumio[1385]: info: ------------------------------ 35ms Aug 31 15:50:49 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status pause Aug 31 15:50:49 volumio-16 sudo[2765]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:50:49 volumio-16 sudo[2765]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:50:49 volumio-16 systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon... Aug 31 15:50:49 volumio-16 volumio[1385]: info: touch_display: Setting screensaver timeout to 0 seconds. Aug 31 15:50:49 volumio-16 systemd[1]: peppymeterbasic.service: Deactivated successfully. Aug 31 15:50:49 volumio-16 systemd[1]: Stopped peppymeterbasic.service - peppymeterbasic Daemon. Aug 31 15:50:49 volumio-16 sudo[2765]: pam_unix(sudo:session): session closed for user root Aug 31 15:50:49 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:51:04 volumio-16 volumio[1385]: info: Preload queue cleared Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioReplaceandPlayItems Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::ClearQueue Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::stop Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::stPlaybackTimer Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::updateTrackBlock Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrackBlock Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:04 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:04 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::serviceStop Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 0 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::serviceStop Aug 31 15:51:04 volumio-16 volumio[1385]: info: [1788205864558] ControllerTidal::stop Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 31 15:51:04 volumio-16 volumio[1385]: info: ControllerMpd::stop Aug 31 15:51:04 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::clearPlayQueue Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::saveQueue Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushQueue Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::addQueueItems Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::addQueueItems Aug 31 15:51:04 volumio-16 volumio[1385]: info: Preload queue cleared Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/508246122 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/508246122 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/468464725 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/468464725 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/423507028 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/423507028 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/452020582 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/452020582 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/444099445 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/444099445 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/489200570 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/489200570 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/514275908 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/514275908 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/499884584 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/499884584 Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.566-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.566-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.566-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.566-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/508246122 title="When the love is gone" Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushQueue Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::saveQueue Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::updateTrackBlock Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrackBlock Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPlay Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::play index 7 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::addQueueItems Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::addQueueItems Aug 31 15:51:04 volumio-16 volumio[1385]: info: Preload queue cleared Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/489200575 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/489200575 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/71266982 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Exploding uri tidal://song/71266982 in service tidal Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/454025173 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/454025173 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/458042479 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/458042479 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/461783067 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/461783067 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/472580872 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/472580872 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/456432807 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/456432807 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/523120820 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/523120820 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/534763546 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/534763546 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Adding Item to queue: tidal://song/492071299 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Using cached record of: tidal://song/492071299 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::stop Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::play index undefined Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::startPlaybackTimer Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetVisibleSources Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 31 15:51:04 volumio-16 volumio[1385]: info: [1788205864587] ControllerTidal::clearAddPlayTrack Aug 31 15:51:04 volumio-16 volumio[1385]: info: Getting stream with soundQuality HI_RES Aug 31 15:51:04 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status stop Aug 31 15:51:04 volumio-16 sudo[2805]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:51:04 volumio-16 sudo[2805]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:04 volumio-16 volumio[1385]: info: Aug 31 15:51:04 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:51:04 volumio-16 volumio[1385]: info: sendMpdCommand stop took 60 milliseconds Aug 31 15:51:04 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:51:04 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:51:04 volumio-16 volumio[1385]: info: sendMpdCommand status took 0 milliseconds Aug 31 15:51:04 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:51:04 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:51:04 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 0 milliseconds Aug 31 15:51:04 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:51:04 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:04 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:04 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:04 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:04 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:04 volumio-16 volumio[1385]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current tidal Received mpd Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.628-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.628-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_STOPPED positionMs=0 volume=100 Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.628-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:04 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:04.629-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:04 volumio-16 sudo[2805]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:04 volumio-16 volumio[1385]: info: ------------------------------ 19ms Aug 31 15:51:04 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status stop Aug 31 15:51:04 volumio-16 sudo[2809]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:51:04 volumio-16 sudo[2809]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:04 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:51:04 volumio-16 sudo[2809]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:04 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:51:05 volumio-16 volumio[1385]: info: getStreamUrl took 443 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand stop Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand stop took 1 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand clear Aug 31 15:51:05 volumio-16 volumio[1385]: info: Aug 31 15:51:05 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:51:05 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand clear took 0 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiQwYjdjZTBkMDhkOWViNzhjMTIzODIzZGFiZmZiZGFhMi5tcDQ/0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==" Aug 31 15:51:05 volumio-16 volumio[1385]: error: updateQueue error: null Aug 31 15:51:05 volumio-16 volumio[1385]: info: Aug 31 15:51:05 volumio-16 volumio[1385]: ---------------------------- MPD announces system playlist update Aug 31 15:51:05 volumio-16 volumio[1385]: info: Ignoring MPD Status Update Aug 31 15:51:05 volumio-16 volumio[1385]: info: ------------------------------ 1ms Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand add "http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiQwYjdjZTBkMDhkOWViNzhjMTIzODIzZGFiZmZiZGFhMi5tcDQ/0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==" took 1 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand play Aug 31 15:51:05 volumio-16 volumio[1385]: info: ------------------------------ 1ms Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand play took 2 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: info: Aug 31 15:51:05 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:51:05 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:51:05 volumio-16 volumio[1385]: info: explodeTIDALUri took 487 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: error: TIDAL Browse Error: failed to get track: got 404: {"status":404,"subStatus":2001,"userMessage":"Track [71266982] not found"} Aug 31 15:51:05 volumio-16 volumio[1385]: error: Commandrouter: Cannot explode uri tidal://song/71266982 from service tidal: failed to get track: got 404: {"status":404,"subStatus":2001,"userMessage":"Track [71266982] not found"} Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushQueue Aug 31 15:51:05 volumio-16 volumio[1385]: info: CorePlayQueue::saveQueue Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::updateTrackBlock Aug 31 15:51:05 volumio-16 volumio[1385]: info: CorePlayQueue::getTrackBlock Aug 31 15:51:05 volumio-16 volumio[1385]: info: Aug 31 15:51:05 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand status took 17 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand status took 1 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:51:05 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":265,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"327 Kbps","isStreaming":false,"title":"0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiQwYjdjZTBkMDhkOWViNzhjMTIzODIzZGFiZmZiZGFhMi5tcDQ/0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","trackType":"tidal"} Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: CURRENT POSITION 7 Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus stop Aug 31 15:51:05 volumio-16 volumio[1385]: info: ------------------------------ 18ms Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 1 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:51:05 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":962,"duration":265,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"407 Kbps","isStreaming":false,"title":"0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiQwYjdjZTBkMDhkOWViNzhjMTIzODIzZGFiZmZiZGFhMi5tcDQ/0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","trackType":"tidal"} Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: CURRENT POSITION 7 Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:51:05 volumio-16 volumio[1385]: info: Received an update from plugin. extracting info from payload Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:05 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:05 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.098-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=249 volume=100 Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.098-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=249 volume=100 Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.098-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.098-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.099-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=249 volume=100 Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.099-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=249 volume=100 Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.099-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.099-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:05 volumio-16 volumio[1385]: info: ------------------------------ 28ms Aug 31 15:51:05 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:51:05 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:51:05 volumio-16 sudo[2817]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:51:05 volumio-16 sudo[2817]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:05 volumio-16 sudo[2815]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:51:05 volumio-16 sudo[2815]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:05 volumio-16 kernel: dma dma2chan2: dma2chan2 is non-idle! Aug 31 15:51:05 volumio-16 systemd[1]: Started peppymeterbasic.service - peppymeterbasic Daemon. Aug 31 15:51:05 volumio-16 sudo[2817]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:05 volumio-16 sudo[2815]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:05 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:51:05 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:51:05 volumio-16 volumio[1385]: info: Aug 31 15:51:05 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:51:05 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:51:05 volumio-16 volumio[1385]: error: MPD returned error for command status: Failed to open audio output Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand clearerror Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand status took 4 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand clearerror took 3 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 3 milliseconds Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:51:05 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":3049,"duration":265,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"383 Kbps","isStreaming":false,"title":"0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiQwYjdjZTBkMDhkOWViNzhjMTIzODIzZGFiZmZiZGFhMi5tcDQ/0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","trackType":"tidal"} Aug 31 15:51:05 volumio-16 volumio[1385]: verbose: CURRENT POSITION 7 Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService pause Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus play Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:05 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:05 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:05 volumio-16 volumio[1385]: info: CoreStateMachine::stPlaybackTimer Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.701-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PAUSED positionMs=751 volume=100 Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.702-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PAUSED positionMs=751 volume=100 Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.702-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:05 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:05.702-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:05 volumio-16 volumio[1385]: info: ------------------------------ 23ms Aug 31 15:51:05 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status pause Aug 31 15:51:05 volumio-16 sudo[2824]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:51:05 volumio-16 sudo[2824]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:05 volumio-16 volumio[1385]: info: touch_display: Setting screensaver timeout to 0 seconds. Aug 31 15:51:05 volumio-16 systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon... Aug 31 15:51:05 volumio-16 systemd[1]: peppymeterbasic.service: Deactivated successfully. Aug 31 15:51:05 volumio-16 systemd[1]: Stopped peppymeterbasic.service - peppymeterbasic Daemon. Aug 31 15:51:05 volumio-16 sudo[2824]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:05 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:51:06 volumio-16 volumio[1385]: info: Executing endpoint metavolumio Aug 31 15:51:06 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 15:51:06 volumio-16 volumio[1385]: info: Executing endpoint metavolumio Aug 31 15:51:06 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 15:51:06 volumio-16 volumio[1385]: info: Executing endpoint metavolumio Aug 31 15:51:06 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 15:51:16 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 15:51:17 volumio-16 volumio[1385]: info: Getting Alsa Cards List without I2S DAC Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 31 15:51:17 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 31 15:51:18 volumio-16 volumio[1385]: info: Executing endpoint metavolumio Aug 31 15:51:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 15:51:18 volumio-16 volumio[1385]: info: Executing endpoint metavolumio Aug 31 15:51:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 15:51:18 volumio-16 volumio[1385]: info: Executing endpoint metavolumio Aug 31 15:51:18 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Aug 31 15:51:38 volumio-16 volumio[1385]: info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object] Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions Aug 31 15:51:38 volumio-16 volumio[1385]: info: Preparing to save Alsa Options, stopping services first Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPause Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::pause Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::stPlaybackTimer Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::servicePause Aug 31 15:51:38 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePause Aug 31 15:51:38 volumio-16 volumio[1385]: info: [1788205898582] ControllerTidal::pause Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 31 15:51:38 volumio-16 volumio[1385]: info: ControllerMpd::pause Aug 31 15:51:38 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand pause Aug 31 15:51:38 volumio-16 volumio[1385]: info: Saving Audio Output to: {"output_device":{"value":"0","label":"HDMI 0 Out"},"i2s":true,"i2sid":{"value":"hifiberry-dacpluspro-pi5","label":"HiFiBerry DAC+ Pro [Pi5]"}} Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: Enabling I2S DAC: HiFiBerry DAC+ Pro [Pi5] Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , enableI2SDAC Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 sudo[2904]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay -l Aug 31 15:51:38 volumio-16 sudo[2904]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 sudo[2904]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 volumio[1385]: info: No Overlays Loaded Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SAlsaName Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 sudo[2907]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/dtoverlay hifiberry-dacplus-pro Aug 31 15:51:38 volumio-16 sudo[2907]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 kernel: OF: overlay: WARNING: memory leak will occur if overlay removed, property: /axi/pcie@1000120000/rp1/i2s@a4000/status Aug 31 15:51:38 volumio-16 kernel: OF: overlay: WARNING: memory leak will occur if overlay removed, property: /axi/pcie@1000120000/rp1/i2c@74000/status Aug 31 15:51:38 volumio-16 kernel: OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc@107c000000/sound/compatible Aug 31 15:51:38 volumio-16 kernel: OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc@107c000000/sound/i2s-controller Aug 31 15:51:38 volumio-16 kernel: OF: overlay: WARNING: memory leak will occur if overlay removed, property: /soc@107c000000/sound/status Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SMixer Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: Found match in i2s Card Database: setting mixer Digital for card HiFiBerry DAC+ Pro [Pi5] Aug 31 15:51:38 volumio-16 sudo[2907]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioUpdateVolumeSettings Aug 31 15:51:38 volumio-16 volumio[1385]: info: Updating Volume Controller Parameters: Device: 2 Name: HiFiBerry DAC+ Pro [Pi5] Mixer: Digital Max Vol: 100 Vol Curve; logarithmic Vol Steps: 1 Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , setExternalVolume Aug 31 15:51:38 volumio-16 volumio[1385]: info: Disabling external Volume Control Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::getUIConfigOnPlugin Aug 31 15:51:38 volumio-16 kernel: pcm512x 1-004d: Failed to reset device: -121 Aug 31 15:51:38 volumio-16 kernel: pcm512x 1-004d: probe with driver pcm512x failed with error -121 Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: wizard , setWizardAction Aug 31 15:51:38 volumio-16 volumio[1385]: info: Preparing to generate the ALSA configuration file Aug 31 15:51:38 volumio-16 volumio[1385]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 31 15:51:38 volumio-16 volumio[1385]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Aug 31 15:51:38 volumio-16 volumio[1385]: info: Reading ALSA contributions from plugins. Aug 31 15:51:38 volumio-16 volumio[1385]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'Digital',0 Aug 31 15:51:38 volumio-16 volumio[1385]: info: I2S Param [object Object] successfully enabled Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 31 15:51:38 volumio-16 volumio[1385]: info: Getting Alsa Cards List without I2S DAC Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2SNumber Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Aug 31 15:51:38 volumio-16 volumio[1385]: info: Aug 31 15:51:38 volumio-16 volumio[1385]: ---------------------------- MPD announces state update: player Aug 31 15:51:38 volumio-16 volumio[1385]: info: sendMpdCommand pause took 132 milliseconds Aug 31 15:51:38 volumio-16 volumio[1385]: info: ControllerMpd::getState Aug 31 15:51:38 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand status Aug 31 15:51:38 volumio-16 volumio[1385]: info: sendMpdCommand status took 0 milliseconds Aug 31 15:51:38 volumio-16 volumio[1385]: verbose: ControllerMpd::parseState Aug 31 15:51:38 volumio-16 volumio[1385]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 31 15:51:38 volumio-16 volumio[1385]: info: VolumeController:: Volume=undefined Mute =false Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:38 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.724-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PAUSED positionMs=1001 volume= Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.724-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PAUSED positionMs=1001 volume= Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.724-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.724-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:38 volumio-16 volumio[1385]: info: sendMpdCommand playlistinfo took 16 milliseconds Aug 31 15:51:38 volumio-16 volumio[1385]: verbose: ControllerMpd::parseTrackInfo Aug 31 15:51:38 volumio-16 volumio[1385]: info: ControllerMpd::pushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::servicePushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: CorePlayQueue::getTrack 7 Aug 31 15:51:38 volumio-16 volumio[1385]: verbose: STATE SERVICE {"status":"play","position":0,"seek":4195,"duration":265,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"399 Kbps","isStreaming":false,"title":"0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","artist":null,"album":null,"uri":"http://lgf.audio.tidal.com/mediatracks/CAEaKAgDEiQwYjdjZTBkMDhkOWViNzhjMTIzODIzZGFiZmZiZGFhMi5tcDQ/0.flac?token=1788209465~NDdlMjY5Y2RjZTRjNTkzYjEwYzVkYTQ3YmZhMTMwY2NjNTJlZDE2NQ==","trackType":"tidal"} Aug 31 15:51:38 volumio-16 volumio[1385]: verbose: CURRENT POSITION 7 Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::syncState stateService play Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::syncState currentStatus pause Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:38 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.742-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=1001 volume= Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.742-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=1001 volume= Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.742-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.742-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:38 volumio-16 volumio[1385]: info: ------------------------------ 36ms Aug 31 15:51:38 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status pause Aug 31 15:51:38 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:51:38 volumio-16 sudo[2949]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop peppymeterbasic.service Aug 31 15:51:38 volumio-16 sudo[2949]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 sudo[2951]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:51:38 volumio-16 sudo[2951]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 sudo[2949]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 sudo[2951]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Stop Aug 31 15:51:38 volumio-16 volumio[1385]: info: Asound.conf file unchanged, so no further update is needed Aug 31 15:51:38 volumio-16 volumio[1385]: info: Output device has changed, restarting MPD Aug 31 15:51:38 volumio-16 volumio[1385]: info: Output device has changed, restarting Shairport Sync Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:38 volumio-16 sudo[2958]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 15:51:38 volumio-16 sudo[2958]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 sudo[2955]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 15:51:38 volumio-16 volumio[1385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 15:51:38 volumio-16 volumio[1385]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:38 volumio-16 sudo[2955]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 volumio[1385]: info: QobuzConnect: setDeactiveState invoked Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:38 volumio-16 vtcs[2567]: [2026-08-31 15:51:38.845] [tisoc] [warning] [SessionManagerImpl.cpp:240] Illegal State: IDLE Aug 31 15:51:38 volumio-16 vtcs[2567]: [2026-08-31 15:51:38.845] [tisoc] [error] [SpkconServer.cpp:378] recv error. socket disconnected Aug 31 15:51:38 volumio-16 sudo[2955]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 sudo[2967]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 31 15:51:38 volumio-16 sudo[2967]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 sudo[2971]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 31 15:51:38 volumio-16 kernel: dma dma2chan2: dma2chan2 failed to stop Aug 31 15:51:38 volumio-16 systemd[1]: Stopping mpd.service - Music Player Daemon... Aug 31 15:51:38 volumio-16 sudo[2971]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.909-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=1001 volume=0 Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.909-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=1001 volume=0 Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.909-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:38 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:38.909-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:38 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic failed to start. Check your configuration Error: Command failed: /usr/bin/sudo /bin/systemctl start peppymeterbasic.service Aug 31 15:51:38 volumio-16 volumio[1385]: Job for peppymeterbasic.service canceled. Aug 31 15:51:38 volumio-16 volumio[1385]: error: Failed to parse min max audio card capabilities, sending default vales: TypeError: Cannot read properties of undefined (reading 'split') Aug 31 15:51:38 volumio-16 volumio[1385]: info: MPD Permissions set Aug 31 15:51:38 volumio-16 volumio[1385]: info: VolumeController::SetAlsaVolume0 Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:38 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:38 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:38 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:38 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:51:38 volumio-16 systemd[1]: Stopping vtcs.service - Volumio Tidal Connect Service... Aug 31 15:51:38 volumio-16 sudo[2977]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 31 15:51:38 volumio-16 systemd[1]: vtcs.service: Deactivated successfully. Aug 31 15:51:38 volumio-16 sudo[2977]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 systemd[1]: Stopped vtcs.service - Volumio Tidal Connect Service. Aug 31 15:51:38 volumio-16 sudo[2977]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 sudo[2980]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 31 15:51:38 volumio-16 sudo[2980]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 sudo[2971]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 sudo[2967]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:38 volumio-16 systemd[1]: Stopping qobuz-connect.service - Volumio Qobuz Connect Service... Aug 31 15:51:38 volumio-16 qobuz-connect[2549]: 20260831 15:51:38.948 [2549.2549] INFO SampleApp: Stopping Local configuration server Aug 31 15:51:38 volumio-16 volumio[1385]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'Digital',0 Aug 31 15:51:38 volumio-16 sudo[2985]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:51:38 volumio-16 systemd[1]: mpd.service: Deactivated successfully. Aug 31 15:51:38 volumio-16 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 15:51:38 volumio-16 systemd[1]: mpd.service: Consumed 1.151s CPU time. Aug 31 15:51:38 volumio-16 sudo[2985]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:38 volumio-16 systemd[1]: mpd.socket: Deactivated successfully. Aug 31 15:51:38 volumio-16 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 15:51:38 volumio-16 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 15:51:38 volumio-16 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 15:51:38 volumio-16 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 15:51:39 volumio-16 systemd[1]: Started peppymeterbasic.service - peppymeterbasic Daemon. Aug 31 15:51:39 volumio-16 sudo[2985]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: info: VolumeController::SetAlsaVolume0 Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreStateMachine::pushState Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioPushState Aug 31 15:51:39 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output update for this device Aug 31 15:51:39 volumio-16 volumio[1385]: info: MRS: Pushing multiroomSync output Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:39 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:39.016-04:00 level=INFO msg="emitting player state changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" state=STATUS_PLAYING positionMs=1001 volume=0 Aug 31 15:51:39 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:39.016-04:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" state=STATUS_PLAYING positionMs=1001 volume=0 Aug 31 15:51:39 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:39.016-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="00:00:00:00:00:00%01,192.168.50.111:49663 @ 0x153ecf0" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:39 volumio-16 volumio5-onboarding[1613]: time=2026-08-31T15:51:39.016-04:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.50.111:49663 @ 0x1721c80" id=tidal://song/499884584 title="A Fathers Love Do Not Let Go" Aug 31 15:51:39 volumio-16 sudo[2989]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 15:51:39 volumio-16 sudo[2989]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 15:51:39 volumio-16 sudo[2989]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: info: PeppyMeterBasic ---peppymeterbasic status play Aug 31 15:51:39 volumio-16 volumio[1385]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: amixer: Unable to find simple control 'Digital',0 Aug 31 15:51:39 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 sudo[2997]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start peppymeterbasic.service Aug 31 15:51:39 volumio-16 sudo[2997]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: Starting Shairport Sync Aug 31 15:51:39 volumio-16 volumio[1385]: info: Preparing to generate the ALSA configuration file Aug 31 15:51:39 volumio-16 sudo[3006]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 15:51:39 volumio-16 sudo[3006]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 volumio[1385]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 31 15:51:39 volumio-16 volumio[1385]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Aug 31 15:51:39 volumio-16 volumio[1385]: info: Reading ALSA contributions from plugins. Aug 31 15:51:39 volumio-16 volumio[1385]: info: Asound.conf file written Aug 31 15:51:39 volumio-16 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 15:51:39 volumio-16 sudo[3010]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 31 15:51:39 volumio-16 sudo[3010]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:51:39 volumio-16 systemd[1]: shairport-sync.service: Consumed 1.540s CPU time. Aug 31 15:51:39 volumio-16 sudo[3010]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: info: Output device has changed, restarting MPD Aug 31 15:51:39 volumio-16 sudo[3006]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[2997]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3017]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 15:51:39 volumio-16 sudo[3017]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3017]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: info: Output device has changed, restarting Shairport Sync Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:39 volumio-16 sudo[3020]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 15:51:39 volumio-16 sudo[3020]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 volumio[1385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 15:51:39 volumio-16 volumio[1385]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: QobuzConnect: setDeactiveState invoked Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:39 volumio-16 systemd[1]: mpd.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 15:51:39 volumio-16 systemd[1]: mpd.socket: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 15:51:39 volumio-16 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 15:51:39 volumio-16 sudo[3044]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 31 15:51:39 volumio-16 sudo[3044]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3047]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 31 15:51:39 volumio-16 sudo[3047]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 15:51:39 volumio-16 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 15:51:39 volumio-16 sudo[3055]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 31 15:51:39 volumio-16 sudo[3055]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3054]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 15:51:39 volumio-16 sudo[3054]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 15:51:39 volumio-16 sudo[3054]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: info: MPD Permissions set Aug 31 15:51:39 volumio-16 volumio[1385]: info: peppymeterbasic Daemon Started Aug 31 15:51:39 volumio-16 volumio[1385]: info: Shairport-Sync Started Aug 31 15:51:39 volumio-16 sudo[3044]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: Starting Shairport Sync Aug 31 15:51:39 volumio-16 volumio[1385]: info: Preparing to generate the ALSA configuration file Aug 31 15:51:39 volumio-16 volumio[1385]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Aug 31 15:51:39 volumio-16 volumio[1385]: info: The plugin peppymeterbasic has an ALSA contribution file peppy_in.peppy_out.6.conf Aug 31 15:51:39 volumio-16 volumio[1385]: info: Reading ALSA contributions from plugins. Aug 31 15:51:39 volumio-16 sudo[3066]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 15:51:39 volumio-16 sudo[3066]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3055]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3047]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 15:51:39 volumio-16 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:51:39 volumio-16 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:51:39 volumio-16 sudo[3066]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: info: Shairport-Sync Started Aug 31 15:51:39 volumio-16 sudo[3070]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 31 15:51:39 volumio-16 sudo[3070]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 volumio[1385]: info: Asound.conf file written Aug 31 15:51:39 volumio-16 sudo[3087]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Aug 31 15:51:39 volumio-16 sudo[3087]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3087]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:1 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:2 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: alsa-lib main.c:1541:(snd_use_case_mgr_open) error: failed to import hw:7 use case configuration -2 Aug 31 15:51:39 volumio-16 volumio[1385]: info: Output device has changed, restarting MPD Aug 31 15:51:39 volumio-16 sudo[3094]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Aug 31 15:51:39 volumio-16 sudo[3094]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3094]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3097]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Aug 31 15:51:39 volumio-16 sudo[3097]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 volumio[1385]: info: Output device has changed, restarting Shairport Sync Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:39 volumio-16 systemd[1]: mpd.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 volumio[1385]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Aug 31 15:51:39 volumio-16 volumio[1385]: info: MRS: Audio Device Changed, rebuilding Multiroom Configuration Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 15:51:39 volumio-16 systemd[1]: mpd.socket: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Closed mpd.socket - Music Player Daemon Socket. Aug 31 15:51:39 volumio-16 systemd[1]: Stopping mpd.socket - Music Player Daemon Socket... Aug 31 15:51:39 volumio-16 volumio[1385]: info: QobuzConnect: setDeactiveState invoked Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::volumioGetState Aug 31 15:51:39 volumio-16 sudo[3107]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 31 15:51:39 volumio-16 sudo[3107]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 systemd[1]: Listening on mpd.socket - Music Player Daemon Socket. Aug 31 15:51:39 volumio-16 systemd[1]: Starting mpd.service - Music Player Daemon... Aug 31 15:51:39 volumio-16 sudo[3107]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3111]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service Aug 31 15:51:39 volumio-16 sudo[3111]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 volumio[1385]: info: MPD Permissions set Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 sudo[3110]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Aug 31 15:51:39 volumio-16 sudo[3110]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Aug 31 15:51:39 volumio-16 sudo[3110]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3119]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service Aug 31 15:51:39 volumio-16 sudo[3119]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 31 15:51:39 volumio-16 volumio[1385]: info: Starting Shairport Sync Aug 31 15:51:39 volumio-16 sudo[3130]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 31 15:51:39 volumio-16 sudo[3130]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3119]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Aug 31 15:51:39 volumio-16 systemd[1]: shairport-sync.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:51:39 volumio-16 sudo[3111]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3132]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service Aug 31 15:51:39 volumio-16 sudo[3132]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Aug 31 15:51:39 volumio-16 sudo[3130]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: info: Shairport-Sync Started Aug 31 15:51:39 volumio-16 volumio[1385]: info: ___________ PLUGINS: Run onVolumioReboot Tasks ___________ Aug 31 15:51:39 volumio-16 volumio[1385]: info: PLUGIN onReboot : networkfs Aug 31 15:51:39 volumio-16 volumio[1385]: info: PLUGIN onReboot : touch_display Aug 31 15:51:39 volumio-16 sudo[3149]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumio-kiosk.service Aug 31 15:51:39 volumio-16 sudo[3149]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 sudo[3157]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reboot Aug 31 15:51:39 volumio-16 sudo[3157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Aug 31 15:51:39 volumio-16 systemd-logind[992]: The system will reboot now! Aug 31 15:51:39 volumio-16 systemd-logind[992]: System is rebooting. Aug 31 15:51:39 volumio-16 sudo[3132]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[2980]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3070]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3097]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3020]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 sudo[3157]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: error: QobuzConnect: could not execute /bin/systemctl to restart qobuz connect process. Reason: Job for qobuz-connect.service canceled. Aug 31 15:51:39 volumio-16 sudo[2958]: pam_unix(sudo:session): session closed for user root Aug 31 15:51:39 volumio-16 volumio[1385]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 15:51:39 volumio-16 volumio[1385]: [UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "undefined".] { Aug 31 15:51:39 volumio-16 volumio[1385]: code: 'ERR_UNHANDLED_REJECTION' Aug 31 15:51:39 volumio-16 volumio[1385]: } Aug 31 15:51:39 volumio-16 volumio[1385]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 31 15:51:39 volumio-16 systemd[1]: Removed slice system-modprobe.slice - Slice /system/modprobe. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped target bluetooth.target - Bluetooth Support. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped target graphical.target - Graphical Interface. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped target ip-changed@eth0.target - IP Address changed on eth0. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped target rpc_pipefs.target. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped target rpcbind.target - RPC Port Mapper. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped target timers.target - Timer Units. Aug 31 15:51:39 volumio-16 systemd[1]: apt-daily-upgrade.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped apt-daily-upgrade.timer - Daily apt upgrade and clean activities. Aug 31 15:51:39 volumio-16 systemd[1]: apt-daily.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped apt-daily.timer - Daily apt download activities. Aug 31 15:51:39 volumio-16 systemd[1]: dpkg-db-backup.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped dpkg-db-backup.timer - Daily dpkg database backup timer. Aug 31 15:51:39 volumio-16 systemd[1]: e2scrub_all.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped e2scrub_all.timer - Periodic ext4 Online Metadata Check for All Filesystems. Aug 31 15:51:39 volumio-16 systemd[1]: fstrim.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped fstrim.timer - Discard unused blocks once a week. Aug 31 15:51:39 volumio-16 systemd[1]: man-db.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped man-db.timer - Daily man-db regeneration. Aug 31 15:51:39 volumio-16 systemd[1]: ntpsec-rotate-stats.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped ntpsec-rotate-stats.timer - Rotate ntpd stats daily. Aug 31 15:51:39 volumio-16 systemd[1]: setdatetime-helper.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped setdatetime-helper.timer - Volumio Time Sync Watchdog Timer. Aug 31 15:51:39 volumio-16 systemd[1]: systemd-tmpfiles-clean.timer: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped systemd-tmpfiles-clean.timer - Daily Cleanup of Temporary Directories. Aug 31 15:51:39 volumio-16 systemd[1]: systemd-rfkill.socket: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Closed systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch. Aug 31 15:51:39 volumio-16 systemd[1]: Unmounting run-rpc_pipefs.mount - RPC Pipe File System... Aug 31 15:51:39 volumio-16 bluealsa[1120]: ../src/ba-adapter.c:144: Freeing adapter: hci0 Aug 31 15:51:39 volumio-16 systemd[1]: Stopping bluealsa.service - BlueALSA service... Aug 31 15:51:39 volumio-16 bluetoothd[961]: Endpoint unregistered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/source/1 Aug 31 15:51:39 volumio-16 systemd[1]: Stopping peppymeterbasic.service - peppymeterbasic Daemon... Aug 31 15:51:39 volumio-16 bluetoothd[961]: Endpoint unregistered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/sink/2 Aug 31 15:51:39 volumio-16 bluetoothd[961]: Endpoint unregistered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/source/2 Aug 31 15:51:39 volumio-16 bluetoothd[961]: Endpoint unregistered: sender=:1.6 path=/org/bluez/hci0/A2DP/SBC/sink/1 Aug 31 15:51:39 volumio-16 systemd[1]: rpi-display-backlight.service - Turns off Raspberry Pi display backlight on shutdown/reboot was skipped because of an unmet condition check (ConditionPathIsDirectory=/proc/device-tree/rpi_backlight). Aug 31 15:51:39 volumio-16 autossh[2395]: received signal to exit (15) Aug 31 15:51:39 volumio-16 systemd[1]: Stopping sshtunnel.service - MyVolumio SSH Tunnel... Aug 31 15:51:39 volumio-16 systemd[1]: Stopping systemd-random-seed.service - Load/Save Random Seed... Aug 31 15:51:39 volumio-16 systemd[1]: Stopping upower.service - Daemon for power management... Aug 31 15:51:39 volumio-16 systemd[1]: Stopping volumio5-onboarding.service - Volumio5 Onboarding Server... Aug 31 15:51:39 volumio-16 systemd[1]: Stopping volumiobt.service - Volumio Bluetooth Module... Aug 31 15:51:39 volumio-16 volumiobt[3178]: INFO [BTSTART] Disconnecting all Bluetooth devices... Aug 31 15:51:39 volumio-16 systemd[1]: bluealsa.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped bluealsa.service - BlueALSA service. Aug 31 15:51:39 volumio-16 systemd[1]: upower.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped upower.service - Daemon for power management. Aug 31 15:51:39 volumio-16 systemd[1]: volumio5-onboarding.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped volumio5-onboarding.service - Volumio5 Onboarding Server. Aug 31 15:51:39 volumio-16 systemd[1]: sshtunnel.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped sshtunnel.service - MyVolumio SSH Tunnel. Aug 31 15:51:39 volumio-16 bluetoothd[961]: Adv Monitor app :1.53 disconnected from D-Bus Aug 31 15:51:39 volumio-16 systemd[1]: mpd.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped mpd.service - Music Player Daemon. Aug 31 15:51:39 volumio-16 systemd[1]: run-rpc_pipefs.mount: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Unmounted run-rpc_pipefs.mount - RPC Pipe File System. Aug 31 15:51:39 volumio-16 systemd[1]: systemd-random-seed.service: Deactivated successfully. Aug 31 15:51:39 volumio-16 systemd[1]: Stopped systemd-random-seed.service - Load/Save Random Seed. Aug 31 15:51:39 volumio-16 volumiobt[3188]: Attempting to disconnect from 77:BC:54:C2:C3:92 Aug 31 15:51:39 volumio-16 volumiobt[3188]: [NEW] Media /org/bluez/hci0 Aug 31 15:51:39 volumio-16 volumiobt[3188]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb Aug 31 15:51:39 volumio-16 volumiobt[3188]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb Aug 31 15:51:39 volumio-16 volumiobt[3188]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb Aug 31 15:51:39 volumio-16 bluetoothd[961]: Path / reserved for Adv Monitor app :1.54 Aug 31 15:51:39 volumio-16 volumiobt[3188]: AdvertisementMonitor path registered Aug 31 15:51:40 volumio-16 sudo[3191]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-08-31 15:50' Aug 31 15:51:40 volumio-16 sudo[3191]: 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"