May 31 16:45:03 volumioht volumio[1247]: warn: [cd-plugin] cdspeedctl: device or media not ready May 31 16:45:03 volumioht volumio[1247]: info: [MyVolumio PluginManager] Starting plugin music_service.smart_inputs May 31 16:45:03 volumioht volumio[1247]: info: Adding inputs REST Endpoints May 31 16:45:03 volumioht volumio[1247]: info: Adding scanAudioInputs REST Endpoint for plugin: music_service/smart_inputs May 31 16:45:03 volumioht volumio[1247]: info: Scanning Audio Inputs May 31 16:45:03 volumioht volumio[1247]: info: Checking against Known Cards name May 31 16:45:03 volumioht volumio[1247]: info: Adding Server instance for streaming May 31 16:45:03 volumioht volumio[1247]: info: [MyVolumio PluginManager] Starting plugin music_service.hi_res_audio May 31 16:45:03 volumioht volumio[1247]: error: Hi Res Audio Failed Login: Missing Login Data May 31 16:45:03 volumioht volumio[1247]: info: Adding HIGHRESAUDIO REST API Endpoints May 31 16:45:03 volumioht volumio[1247]: info: Adding saveAccountData_hi_res_audio REST Endpoint for plugin: music_service/hi_res_audio May 31 16:45:03 volumioht volumio[1247]: info: [MyVolumio PluginManager] Starting plugin music_service.tidal May 31 16:45:03 volumioht volumio[1247]: info: Refreshing TIDAL token May 31 16:45:03 volumioht volumio[1247]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuz May 31 16:45:03 volumioht volumio[1247]: info: [MyVolumio PluginManager] Starting plugin music_service.tidalconnect May 31 16:45:03 volumioht volumio[1247]: info: [MyVolumio PluginManager] Starting plugin music_service.qobuzconnect May 31 16:45:03 volumioht volumio[1247]: info: Adding qc_getconfig REST Endpoint for plugin: music_service/qobuzconnect May 31 16:45:03 volumioht volumio[1247]: info: QobuzConnect: Starting Qobuz Connect socket and service May 31 16:45:03 volumioht sudo[2036]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop vtcs.service May 31 16:45:03 volumioht sudo[2036]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:03 volumioht volumio[1247]: info: QobuzConnect: Opened /tmp/qbz-connect.socket socket, listening for connections May 31 16:45:03 volumioht sudo[2043]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl reset-failed qobuz-connect.service May 31 16:45:03 volumioht sudo[2043]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:03 volumioht volumio[1247]: info: Stopping AccessToken refresher cron for QOBUZ May 31 16:45:03 volumioht sudo[2036]: pam_unix(sudo:session): session closed for user root May 31 16:45:03 volumioht sudo[2043]: pam_unix(sudo:session): session closed for user root May 31 16:45:03 volumioht sudo[2046]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart qobuz-connect.service May 31 16:45:03 volumioht sudo[2046]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:03 volumioht volumio[1247]: info: AccessToken refresher cron started for QOBUZ May 31 16:45:03 volumioht volumio[1247]: info: Adding QOBUZ REST API Endpoints May 31 16:45:04 volumioht volumio[1247]: info: MRS: Getting audio outputs on start May 31 16:45:04 volumioht volumio[1247]: info: MRS: Requesting all other devices output May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetBrowseSources May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 16:45:04 volumioht systemd[1]: Started qobuz-connect.service - Volumio Qobuz Connect Service. May 31 16:45:04 volumioht sudo[2046]: pam_unix(sudo:session): session closed for user root May 31 16:45:04 volumioht volumio[1247]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 31 16:45:04 volumioht volumio[1247]: ------------------------------------ BT MESSAGE: Bluetooth adapter powered on May 31 16:45:04 volumioht sudo[2050]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service May 31 16:45:04 volumioht volumio[1247]: info: MPD Permissions set May 31 16:45:04 volumioht sudo[2050]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:04 volumioht systemd[1]: Started volumiobt.service - Volumio Bluetooth Module. May 31 16:45:04 volumioht sudo[2050]: pam_unix(sudo:session): session closed for user root May 31 16:45:04 volumioht volumiobt[2054]: INFO [BTSTART] Ensuring Bluetooth directory exists... May 31 16:45:04 volumioht sudo[2055]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/mkdir -p /var/lib/bluetooth May 31 16:45:04 volumioht sudo[2055]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:04 volumioht sudo[2055]: pam_unix(sudo:session): session closed for user root May 31 16:45:04 volumioht sudo[2057]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth May 31 16:45:04 volumioht sudo[2057]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:04 volumioht sudo[2057]: pam_unix(sudo:session): session closed for user root May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 31 16:45:04 volumioht volumio[1247]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 31 16:45:04 volumioht volumiobt[2059]: INFO [BTSTART] Powering on Bluetooth if needed... May 31 16:45:04 volumioht bluetoothd[812]: Adv Monitor app :1.25 disconnected from D-Bus May 31 16:45:04 volumioht volumiobt[2062]: INFO [BTSTART] Making Bluetooth discoverable and pairable... May 31 16:45:04 volumioht volumio[1247]: info: Received Get System Version May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 31 16:45:04 volumioht volumio[1247]: info: Received Get System Info May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 31 16:45:04 volumioht volumio[1247]: info: Discovery: Getting this device information May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:04 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:04 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 31 16:45:04 volumioht volumiobt[2063]: [198B blob data] May 31 16:45:04 volumioht volumiobt[2063]: [162B blob data] May 31 16:45:04 volumioht volumiobt[2063]: [162B blob data] May 31 16:45:04 volumioht volumiobt[2063]: [162B blob data] May 31 16:45:04 volumioht volumiobt[2063]: [118B blob data] May 31 16:45:04 volumioht volumiobt[2063]: [7A-14-70-81-63-43]> discoverable on May 31 16:45:04 volumioht volumiobt[2063]: Warning: setting discoverable while discoverable-timeout not set(0) is not recommended May 31 16:45:04 volumioht volumiobt[2063]: [7A-14-70-81-63-43]> pairable on May 31 16:45:04 volumioht bluetoothd[812]: Path / reserved for Adv Monitor app :1.26 May 31 16:45:04 volumioht bluetoothd[812]: Adv Monitor app :1.26 disconnected from D-Bus May 31 16:45:04 volumioht volumiobt[2063]: [7A-14-70-81-63-43]> May 31 16:45:04 volumioht volumiobt[2064]: INFO [BTSTART] Registering Bluetooth agent... May 31 16:45:04 volumioht volumiobt[2065]: [NEW] Media /org/bluez/hci0 May 31 16:45:04 volumioht volumiobt[2065]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb May 31 16:45:04 volumioht volumiobt[2065]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb May 31 16:45:04 volumioht volumiobt[2065]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb May 31 16:45:04 volumioht bluetoothd[812]: Adv Monitor app :1.27 disconnected from D-Bus May 31 16:45:04 volumioht volumiobt[2066]: No agent is registered May 31 16:45:04 volumioht volumiobt[2066]: [NEW] Media /org/bluez/hci0 May 31 16:45:04 volumioht volumiobt[2066]: SupportedUUIDs: 0000110a-0000-1000-8000-00805f9b34fb May 31 16:45:04 volumioht volumiobt[2066]: SupportedUUIDs: 0000110b-0000-1000-8000-00805f9b34fb May 31 16:45:04 volumioht volumiobt[2066]: SupportedUUIDs: 0000FDF0-0000-1000-8000-00805f9b34fb May 31 16:45:04 volumioht bluetoothd[812]: Adv Monitor app :1.28 disconnected from D-Bus May 31 16:45:04 volumioht volumiobt[2067]: INFO [BTSTART] Agent registered successfully. May 31 16:45:04 volumioht volumiobt[2068]: INFO [BTSTART] Starting A2DP agent (a2dp-agent)... May 31 16:45:04 volumioht volumio[1247]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] Connecting to system D-Bus May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] Connected to system D-Bus May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 bluezutils [INFO] Found adapter at: /org/bluez/hci0 May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] Found Bluetooth adapter: /org/bluez/hci0 May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] Set DiscoverableTimeout to infinite May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] Enabled Discoverable mode May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] Agent registered at /local/a2dpagent May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] Agent set as default May 31 16:45:05 volumioht volumiobt[2069]: 2026-05-31 16:45:05 a2dp-agent [INFO] A2DP agent running, waiting for connections... May 31 16:45:05 volumioht volumio[1247]: info: Executing endpoint qc_getconfig May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: qobuzconnect , onGetConfig May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.627 [2048.2048] INFO SampleApp: Started connection to /tmp/qbz-connect.socket UNIX socket May 31 16:45:05 volumioht volumio[1247]: ------------------------------------ BT MESSAGE: volumiobt.service started successfully May 31 16:45:05 volumioht volumio[1247]: ------------------------------------ BT MESSAGE: [FUNC] dbusStart May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.721 [2048.2048] INFO VolumeManager: [0x1e77d48]: Setting new playback volume: 75 May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.721 [2048.2048] INFO VolumeManager: [0x1e77d48]: Setting new mute state: 0 May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.721 [2048.2048] INFO AudioStreamManager: [0x1e77aa0]: Setting new audio download buffer size: 1048576 May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.721 [2048.2048] INFO QobuzConnect: [0x1e78610]: Client initialized! May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.721 [2048.2048] INFO SampleApp: Starting Avahi advertising, name: VolumioHT, service name: _qobuz-connect._tcp May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.740 [2048.2048] INFO LocalConfigManager: [0x1e777c8]: Starting Local Configuration server May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.740 [2048.2048] INFO SampleApp: Starting Local configuration server May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.741 [2048.2048] INFO SampleApp: Connected to UNIX socket client 0x1e62818 May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:05 volumioht qobuz-connect[2048]: 20260531 16:45:05.777 [2048.2048] INFO SampleApp: Playback volume changed: 75 May 31 16:45:05 volumioht volumio[1247]: error: updateQueue error: null May 31 16:45:05 volumioht volumio[1247]: info: QobuzConnect: Qobuz Connect socket /tmp/qbz-connect.socket connected to client [object Object] May 31 16:45:05 volumioht volumio[1247]: info: QobuzConnect: QOBUZ Connect daemon connected May 31 16:45:05 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:05 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:05 volumioht volumio[1247]: info: Access Token successfully retrieved May 31 16:45:05 volumioht volumio[1247]: info: Starting Shairport Sync May 31 16:45:06 volumioht sudo[2081]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 31 16:45:06 volumioht sudo[2081]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:06 volumioht systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... May 31 16:45:06 volumioht systemd[1]: shairport-sync.service: Deactivated successfully. May 31 16:45:06 volumioht systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 31 16:45:06 volumioht systemd[1]: shairport-sync.service: Consumed 1.405s CPU time. May 31 16:45:06 volumioht systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. May 31 16:45:06 volumioht sudo[2081]: pam_unix(sudo:session): session closed for user root May 31 16:45:06 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:06 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:06 volumioht volumio[1247]: info: MRS: Found cast device: Chromecast-Audio-abaf694705d16326f39eb6eb1e91cdbe May 31 16:45:06 volumioht volumio[1247]: info: Adding audio output: May 31 16:45:06 volumioht volumio[1247]: info: Shairport-Sync Started May 31 16:45:06 volumioht volumio[1247]: info: Successfully retrieved User Session From TIDAL May 31 16:45:06 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:06 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:07 volumioht volumio[1247]: info: Successfully retrieved User Subscription From TIDAL May 31 16:45:07 volumioht volumio[1247]: info: Adding TIDAL to Browse Sources May 31 16:45:07 volumioht volumio[1247]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 31 16:45:07 volumioht volumio[1247]: info: [1780256707194] CoreMusicLibrary::Adding element TIDAL May 31 16:45:07 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 31 16:45:07 volumioht volumio[1247]: Cannot find translation for source Spotify May 31 16:45:07 volumioht volumio[1247]: Cannot find translation for source TIDAL May 31 16:45:07 volumioht volumio[1247]: info: Adding TIDAL REST API Endpoints May 31 16:45:07 volumioht volumio[1247]: info: TidalConnect service stoped! May 31 16:45:07 volumioht volumio[1247]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect May 31 16:45:07 volumioht volumio[1247]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect May 31 16:45:08 volumioht sudo[2108]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service May 31 16:45:08 volumioht sudo[2108]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:45:08 volumioht systemd[1]: Started vtcs.service - Volumio Tidal Connect Service. May 31 16:45:08 volumioht sudo[2108]: pam_unix(sudo:session): session closed for user root May 31 16:45:08 volumioht volumio[1247]: info: Executing endpoint tc_getconfig May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig May 31 16:45:08 volumioht vtcs[2111]: STARTING TidalConnect services, version: 1.6.1 May 31 16:45:08 volumioht vtcs[2111]: STARTED TidalConnect services. May 31 16:45:08 volumioht volumio[1247]: info: Executing endpoint tc_connect May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect May 31 16:45:08 volumioht volumio[1247]: info: Connecting to TidalConnect May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::servicePushState May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::pushState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioPushState May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output update for this device May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} May 31 16:45:08 volumioht volumio[1247]: verbose: CURRENT POSITION 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::syncState stateService stop May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::syncState currentStatus stop May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::pushState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioPushState May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output update for this device May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: No code May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::pushState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioPushState May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output update for this device May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::servicePushState May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::pushState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioPushState May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output update for this device May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: verbose: STATE SERVICE {"status":"stop","service":"tidalconnect","title":"","artist":"","album":"","albumart":"/albumart","uri":"","icon":"fa fa-spinner","trackType":"tidal","codec":"","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"","channels":2,"random":false,"repeat":false,"repeatSingle":false} May 31 16:45:08 volumioht volumio[1247]: verbose: CURRENT POSITION 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::syncState stateService stop May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::syncState currentStatus stop May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::pushState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioPushState May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output update for this device May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: No code May 31 16:45:08 volumioht volumio[1247]: info: CoreStateMachine::pushState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioPushState May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output update for this device May 31 16:45:08 volumioht volumio[1247]: info: MRS: Pushing multiroomSync output May 31 16:45:08 volumioht volumio[1247]: info: CoreCommandRouter::volumioGetState May 31 16:45:08 volumioht volumio[1247]: info: CorePlayQueue::getTrack 0 May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.507-03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" state=STATUS_STOPPED positionMs=0 volume=100 May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.507-03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" id= title= May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.549-03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" state=STATUS_STOPPED positionMs=0 volume=100 May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.550-03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" id= title= May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.552-03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" state=STATUS_STOPPED positionMs=0 volume=100 May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.552-03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" id= title= May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.558-03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" state=STATUS_STOPPED positionMs=0 volume=100 May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.558-03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" id= title= May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.560-03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" state=STATUS_STOPPED positionMs=0 volume=100 May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.560-03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" id= title= May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.582-03:00 level=INFO msg="emitting player state changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" state=STATUS_STOPPED positionMs=0 volume=100 May 31 16:45:08 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:08.583-03:00 level=INFO msg="emitting player metadata changed event" component=server peer="192.168.15.32:59026,00:00:00:00:00:00%01 @ 0x2355470" id= title= May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: SPOTIFY VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: DELTA VOLUME ENOUGH: false May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: SPOTIFY VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: DELTA VOLUME ENOUGH: false May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: SPOTIFY VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: DELTA VOLUME ENOUGH: false May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: SPOTIFY VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: DELTA VOLUME ENOUGH: false May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: SPOTIFY VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: DELTA VOLUME ENOUGH: false May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: SPOTIFY VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: VOLUMIO VOLUME 100 May 31 16:45:08 volumioht volumio[1247]: SPOTIFY: DELTA VOLUME ENOUGH: false May 31 16:45:11 volumioht volumio[1247]: info: TidalConnect service started! May 31 16:45:11 volumioht volumio[1247]: [Metrics] CommandRouter: 62s 685.29ms May 31 16:45:11 volumioht volumio[1247]: info: CoreCommandRouter::volumiosetStartupVolume May 31 16:45:11 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 31 16:45:11 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 16:45:11 volumioht volumio[1247]: info: CoreCommandRouter::Close All Modals sent May 31 16:45:11 volumioht volumio[1247]: info: CoreCommandRouter::Close All Modals sent May 31 16:45:12 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable May 31 16:45:12 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 31 16:45:12 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect May 31 16:45:18 volumioht volumio[1247]: info: BOOT COMPLETED May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode May 31 16:45:21 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus May 31 16:45:26 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 16:45:26 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 16:45:26 volumioht kernel: vc4-drm gpu: [drm] *ERROR* [CRTC:100:pixelvalve-2] flip_done timed out May 31 16:45:29 volumioht volumio[1247]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 16:45:29 volumioht volumio[1247]: info: touch_display: About to detect HDMI ports... May 31 16:45:29 volumioht volumio[1247]: info: touch_display: X server not ready, cannot detect HDMI ports yet. May 31 16:45:29 volumioht go-librespot[1696]: time="2026-05-31T16:45:29-03:00" level=trace msg="sent dealer ping" May 31 16:45:29 volumioht go-librespot[1696]: time="2026-05-31T16:45:29-03:00" level=trace msg="received dealer pong" May 31 16:45:35 volumioht volumio[1247]: info: CALLMETHOD: user_interface touch_display saveScreensaverConf [object Object] May 31 16:45:35 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: touch_display , saveScreensaverConf May 31 16:45:35 volumioht volumio[1247]: error: touch_display: Error waking up the screen: Error: Command failed: /usr/bin/xset -display :undefined s reset dpms force on May 31 16:45:35 volumioht volumio[1247]: /usr/bin/xset: unable to open display ":undefined" May 31 16:45:35 volumioht volumio[1247]: error: touch_display: Error setting screensaver timeout: Error: ENOENT: no such file or directory, stat '/tmp/.X11-unix/Xundefined' May 31 16:45:36 volumioht kernel: vc4-drm gpu: [drm] *ERROR* flip_done timed out May 31 16:45:36 volumioht kernel: vc4-drm gpu: [drm] *ERROR* [CRTC:100:pixelvalve-2] commit wait timed out May 31 16:45:38 volumioht volumio[1247]: info: CALLMETHOD: user_interface touch_display saveScreensaverConf [object Object] May 31 16:45:38 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: touch_display , saveScreensaverConf May 31 16:45:46 volumioht dbus-daemon[711]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.16" (uid=0 pid=1529 comm="/usr/bin/volumio5-onboarding") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply="0" destination=":1.4" (uid=0 pid=812 comm="/usr/libexec/bluetooth/bluetoothd --noplugin=sap,b") May 31 16:45:47 volumioht kernel: vc4-drm gpu: [drm] *ERROR* flip_done timed out May 31 16:45:47 volumioht kernel: vc4-drm gpu: [drm] *ERROR* [CONNECTOR:33:HDMI-A-1] commit wait timed out May 31 16:45:47 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 16:45:47 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 16:45:49 volumioht volumio5-onboarding[1529]: time=2026-05-31T16:45:49.290-03:00 level=WARN msg="pending write exceeded maximum retries, dropping" component=ble/conn addr=1 chunks=1 index=0 tries=11 May 31 16:45:51 volumioht volumio[1247]: info: CoreCommandRouter::getUIConfigOnPlugin May 31 16:45:51 volumioht volumio[1247]: info: touch_display: About to detect HDMI ports... May 31 16:45:51 volumioht volumio[1247]: info: touch_display: X server not ready, cannot detect HDMI ports yet. May 31 16:45:57 volumioht kernel: vc4-drm gpu: [drm] *ERROR* flip_done timed out May 31 16:45:57 volumioht kernel: vc4-drm gpu: [drm] *ERROR* [PLANE:89:plane-3] commit wait timed out May 31 16:45:59 volumioht go-librespot[1696]: time="2026-05-31T16:45:59-03:00" level=trace msg="sent dealer ping" May 31 16:45:59 volumioht go-librespot[1696]: time="2026-05-31T16:45:59-03:00" level=trace msg="received dealer pong" May 31 16:46:01 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 31 16:46:01 volumioht volumio[1247]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 31 16:46:07 volumioht kernel: vc4-drm gpu: [drm] *ERROR* flip_done timed out May 31 16:46:07 volumioht kernel: vc4-drm gpu: [drm] *ERROR* Timed out waiting for commit May 31 16:46:17 volumioht volumio[1247]: info: Starting Uninstall of plugin user_interface - touch_display May 31 16:46:17 volumioht volumio[1247]: info: Uninstalling plugin touch_display May 31 16:46:17 volumioht volumio[1247]: info: touch_display: Un-/commenting gpu_mem settings in /boot/config.txt. May 31 16:46:17 volumioht sudo[2249]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod a+rw /etc/X11/xorg.conf.d/95-touch_display-plugin.conf May 31 16:46:17 volumioht sudo[2249]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:46:17 volumioht sudo[2249]: pam_unix(sudo:session): session closed for user root May 31 16:46:17 volumioht sudo[2251]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start getty@tty1.service May 31 16:46:17 volumioht sudo[2253]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable getty@tty1.service May 31 16:46:17 volumioht sudo[2251]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:46:17 volumioht sudo[2253]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:46:17 volumioht volumio[1247]: info: touch_display: Using /boot/config.txt instead of /boot/userconfig.txt. May 31 16:46:17 volumioht volumio[1247]: info: touch_display: File permissions for /etc/X11/xorg.conf.d/95-touch_display-plugin.conf set. May 31 16:46:17 volumioht volumio[1247]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 16:46:17 volumioht sudo[2258]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumio-kiosk.service May 31 16:46:17 volumioht sudo[2258]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) May 31 16:46:17 volumioht kernel: vc4-drm gpu: [drm] *ERROR* [CRTC:100:pixelvalve-2] flip_done timed out May 31 16:46:17 volumioht volumio[1247]: TypeError: Cannot read properties of undefined (reading 'split') May 31 16:46:17 volumioht volumio[1247]: at /data/plugins/user_interface/touch_display/index.js:1298:37 May 31 16:46:17 volumioht volumio[1247]: at ChildProcess.exithandler (node:child_process:413:7) May 31 16:46:17 volumioht volumio[1247]: at ChildProcess.emit (node:events:514:28) May 31 16:46:17 volumioht volumio[1247]: at maybeClose (node:internal/child_process:1105:16) May 31 16:46:17 volumioht volumio[1247]: at Socket. (node:internal/child_process:457:11) May 31 16:46:17 volumioht volumio[1247]: at Socket.emit (node:events:514:28) May 31 16:46:17 volumioht volumio[1247]: at Pipe. (node:net:337:12) May 31 16:46:17 volumioht systemd[1]: Reloading. May 31 16:46:17 volumioht volumio[1247]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 31 16:46:18 volumioht systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 31 16:46:18 volumioht systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. May 31 16:46:18 volumioht 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. May 31 16:46:18 volumioht 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. May 31 16:46:18 volumioht systemd[1]: Created slice system-getty.slice - Slice /system/getty. May 31 16:46:18 volumioht sudo[2253]: pam_unix(sudo:session): session closed for user root May 31 16:46:19 volumioht systemd[1]: Started getty@tty1.service - Getty on tty1. May 31 16:46:19 volumioht sudo[2251]: pam_unix(sudo:session): session closed for user root May 31 16:46:19 volumioht sudo[2258]: pam_unix(sudo:session): session closed for user root May 31 16:46:20 volumioht sudo[2292]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-31 16:45' May 31 16:46:20 volumioht sudo[2292]: 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"