Jan 11 11:32:01 volumio volumio[1167]: info: CoreCommandRouter::Close All Modals sent Jan 11 11:32:07 volumio volumio[1167]: info: CALLMETHOD: system_hardware Bluetoothremote saveBT [object Object] Jan 11 11:32:07 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: Bluetoothremote , saveBT Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- Attempting to stop Bluetooth scan... Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- bluetoothctl scan off command sent. Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- Scan timeout cleared manually. Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- Starting pairing with device: 9D:F7:50:2D:A0:10 Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- Sending command: power on Jan 11 11:32:07 volumio volumio[1167]: error: Failed callmethod call: TypeError: self.pairBtDevice(...).then(...).catch is not a function Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- Waiting to connect to bluetoothd... Jan 11 11:32:07 volumio volumio[1167]: [58B blob data] Jan 11 11:32:07 volumio volumio[1167]: [133B blob data] Jan 11 11:32:07 volumio volumio[1167]: [157B blob data] Jan 11 11:32:07 volumio volumio[1167]: [182B blob data] Jan 11 11:32:07 volumio volumio[1167]: [157B blob data] Jan 11 11:32:07 volumio volumio[1167]: [bluetoothctl]> Jan 11 11:32:07 volumio volumio[1167]: [133B blob data] Jan 11 11:32:07 volumio volumio[1167]: [bluetoothctl]> Jan 11 11:32:07 volumio volumio[1167]: [166B blob data] Jan 11 11:32:07 volumio volumio[1167]: [157B blob data] Jan 11 11:32:07 volumio volumio[1167]: [157B blob data] Jan 11 11:32:07 volumio volumio[1167]: [bluetoothctl]> Jan 11 11:32:07 volumio volumio[1167]: [122B blob data] Jan 11 11:32:07 volumio volumio[1167]: [bluetoothctl]> Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- power on Jan 11 11:32:07 volumio volumio[1167]: info: Bluetoothremote--- [bluetoothctl]> Jan 11 11:32:07 volumio bluetoothd[917]: Path / reserved for Adv Monitor app :1.41 Jan 11 11:32:07 volumio volumio[1167]: [142B blob data] Jan 11 11:32:07 volumio volumio[1167]: [bluetoothctl]> Jan 11 11:32:07 volumio volumio[1167]: [133B blob data] Jan 11 11:32:07 volumio volumio[1167]: [bluetoothctl]> Jan 11 11:32:10 volumio volumio[1167]: info: Bluetoothremote--- Sending command: pair 9D:F7:50:2D:A0:10 Jan 11 11:32:10 volumio volumio[1167]: info: Bluetoothremote--- pair 9D:F7:50:2D:A0:10 Jan 11 11:32:10 volumio volumio[1167]: info: Bluetoothremote--- Attempting to pair with 9D:F7:50:2D:A0:10 Jan 11 11:32:10 volumio volumio[1167]: [bluetoothctl]> Jan 11 11:32:10 volumio volumio[1167]: [165B blob data] Jan 11 11:32:10 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:10 volumio volumio[1167]: [148B blob data] Jan 11 11:32:10 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:11 volumio bluealsa[989]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_9D_F7_50_2D_A0_10, ...) Jan 11 11:32:11 volumio volumio[1167]: [172B blob data] Jan 11 11:32:11 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:11 volumio volumio[1167]: [180B blob data] Jan 11 11:32:11 volumio volumio[1167]: [168B blob data] Jan 11 11:32:11 volumio volumio[1167]: [168B blob data] Jan 11 11:32:11 volumio volumio[1167]: [168B blob data] Jan 11 11:32:11 volumio volumio[1167]: [146B blob data] Jan 11 11:32:11 volumio volumio[1167]: [136B blob data] Jan 11 11:32:11 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:11 volumio volumio[1167]: [124B blob data] Jan 11 11:32:11 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:12 volumio volumio[1167]: info: Bluetoothremote--- Sending command: trust 9D:F7:50:2D:A0:10 Jan 11 11:32:12 volumio volumio[1167]: info: Bluetoothremote--- trust 9D:F7:50:2D:A0:10 Jan 11 11:32:12 volumio volumio[1167]: info: Bluetoothremote--- [PBL 40 A1]> Jan 11 11:32:12 volumio volumio[1167]: [149B blob data] Jan 11 11:32:12 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:12 volumio volumio[1167]: [148B blob data] Jan 11 11:32:12 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio volumio[1167]: info: Bluetoothremote--- Sending command: connect 9D:F7:50:2D:A0:10 Jan 11 11:32:15 volumio volumio[1167]: info: Bluetoothremote--- connect 9D:F7:50:2D:A0:10 Jan 11 11:32:15 volumio volumio[1167]: info: Bluetoothremote--- Jan 11 11:32:15 volumio volumio[1167]: Attempting to connect to 9D:F7:50:2D:A0:10 Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_9D_F7_50_2D_A0_10/sep1, ...) Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1362: Adding new Stream End-Point: 9D:F7:50:2D:A0:10: SNK: SBC Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_9D_F7_50_2D_A0_10/sep2, ...) Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1362: Adding new Stream End-Point: 9D:F7:50:2D:A0:10: SNK: SBC Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_9D_F7_50_2D_A0_10/sep3, ...) Jan 11 11:32:15 volumio volumio[1167]: [163B blob data] Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1362: Adding new Stream End-Point: 9D:F7:50:2D:A0:10: SNK: SBC Jan 11 11:32:15 volumio bluealsa[989]: ../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/SBC/source/1 Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:429: A2DP peer capabilities blob [len=4]: ffff0235 Jan 11 11:32:15 volumio volumio[1167]: [163B blob data] Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio volumio[1167]: [163B blob data] Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_9D_F7_50_2D_A0_10/sep1/fd0, ...) Jan 11 11:32:15 volumio bluealsa[989]: ../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/source/1 Jan 11 11:32:15 volumio bluealsa[989]: ../src/a2dp-sbc.c:536: SBC: Selected bit-pool range: [2, 53] Jan 11 11:32:15 volumio bluealsa[989]: ../src/storage.c:123: Loading storage: /var/lib/bluealsa/9D:F7:50:2D:A0:10 Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:572: A2DP Source (SBC) configured for device 9D:F7:50:2D:A0:10 Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:575: A2DP selected configuration blob [len=4]: 11150235 Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:577: PCM configuration: channels: 2, sampling: 48000 Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/source/3 Jan 11 11:32:15 volumio bluetoothd[917]: Endpoint registered: sender=:1.7 path=/org/bluez/hci0/A2DP/SBC/source/3 Jan 11 11:32:15 volumio volumio[1167]: [168B blob data] Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio volumio[1167]: [181B blob data] Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio volumio[1167]: [127B blob data] Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio volumio[1167]: info: Bluetoothremote--- ✅ Connection confirmed: PBL 40 A1 (9D:F7:50:2D:A0:10) Jan 11 11:32:15 volumio kernel: input: PBL 40 A1 (AVRCP) as /devices/virtual/input/input0 Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1480: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume Jan 11 11:32:15 volumio bluealsa[989]: bluez.c:1498: Skipping A2DP volume update: 24 Jan 11 11:32:15 volumio volumio[1167]: ------------------------------------ BT MESSAGE: [DEBUG] registerVolumeHandler: MAC = 9D:F7:50:2D:A0:10, rawVolume = 24 Jan 11 11:32:15 volumio volumio[1167]: ------------------------------------ BT MESSAGE: Received volume: raw = 24, scaled = 19 Jan 11 11:32:15 volumio volumio[1167]: info: VolumeController::SetAlsaVolume19 Jan 11 11:32:15 volumio volumio[1167]: ------------------------------------ BT MESSAGE: [WARN] pushMultiRoomVolume is not available Jan 11 11:32:15 volumio volumio[1167]: info: VolumeController::SetAlsaVolume19 Jan 11 11:32:15 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:32:15 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 11:32:15 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:32:15 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:32:15 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:32:15 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:32:15 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:32:15 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:32:15 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:32:15 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:32:15 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:32:15 volumio systemd[1]: Stopping triggerhappy.service - triggerhappy global hotkey daemon... Jan 11 11:32:15 volumio volumio[1167]: [188B blob data] Jan 11 11:32:15 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:15 volumio systemd[1]: triggerhappy.service: Deactivated successfully. Jan 11 11:32:15 volumio systemd[1]: Stopped triggerhappy.service - triggerhappy global hotkey daemon. Jan 11 11:32:15 volumio volumio[1167]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.iXnFomCZSsVdoSzQS55mRCjXNxL2.b4bc9887e2ed86be628f86dd25d081b4.state.status' Jan 11 11:32:15 volumio systemd[1]: Starting triggerhappy.service - triggerhappy global hotkey daemon... Jan 11 11:32:15 volumio systemd[1]: Started triggerhappy.service - triggerhappy global hotkey daemon. Jan 11 11:32:15 volumio systemd-logind[709]: Watching system buttons on /dev/input/event0 (PBL 40 A1 (AVRCP)) Jan 11 11:32:17 volumio volumio[1167]: info: Bluetoothremote--- Waiting for device to confirm connection... Jan 11 11:32:17 volumio volumio[1167]: info: Bluetoothremote--- quit Jan 11 11:32:17 volumio volumio[1167]: [PBL 40 A1]> Jan 11 11:32:17 volumio volumio[1167]: info: Bluetoothremote--- Jan 11 11:32:17 volumio bluetoothd[917]: Adv Monitor app :1.41 disconnected from D-Bus Jan 11 11:32:17 volumio volumio[1167]: info: Bluetoothremote--- bluetoothctl exited with code 0 Jan 11 11:32:17 volumio volumio[1167]: info: Bluetoothremote--- Device list cleared and placeholder written. Jan 11 11:32:17 volumio volumio[1167]: info: Bluetoothremote--- Device paired successfully Jan 11 11:32:18 volumio volumio[1167]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 11:32:18 volumio volumio[1167]: info: CoreCommandRouter::getUIConfigOnPlugin Jan 11 11:32:18 volumio volumio[1167]: info: Bluetoothremote--- Device found: Press scan to detect BT device - xx Jan 11 11:32:18 volumio volumio[1167]: info: Bluetoothremote--- Device found: Press scan to detect BT device - xx Jan 11 11:32:18 volumio bluetoothd[917]: Path / reserved for Adv Monitor app :1.42 Jan 11 11:32:18 volumio bluetoothd[917]: Path / reserved for Adv Monitor app :1.43 Jan 11 11:32:18 volumio bluetoothd[917]: Adv Monitor app :1.42 disconnected from D-Bus Jan 11 11:32:18 volumio bluetoothd[917]: Adv Monitor app :1.43 disconnected from D-Bus Jan 11 11:32:19 volumio bluealsa[989]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_37_3F_FA_82_33_88, ...) Jan 11 11:32:19 volumio bluealsa[989]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_6A_5D_84_2D_0C_1A, ...) Jan 11 11:32:22 volumio volumio[1167]: info: CoreCommandRouter::Close All Modals sent Jan 11 11:32:23 volumio bluealsa[989]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_79_55_FF_A0_17_B7, ...) Jan 11 11:32:24 volumio bluealsa[989]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_51_BB_26_FD_9E_D8, ...) Jan 11 11:32:25 volumio bluealsa[989]: bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_5C_B2_6D_3A_3E_81, ...) Jan 11 11:32:33 volumio volumio[1167]: info: CoreCommandRouter::volumioVolatilePlay Jan 11 11:32:33 volumio volumio[1167]: ------------------------------------ BT MESSAGE: [FUNC] play Jan 11 11:32:33 volumio volumio[1167]: ------------------------------------ BT MESSAGE: sendPlay skipped: activePlayer not bound or invalid Jan 11 11:32:44 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Jan 11 11:32:44 volumio volumio[1167]: info: CURURI: artists:// Jan 11 11:32:44 volumio volumio[1167]: info: CoreCommandRouter::volumioGetQueue Jan 11 11:32:44 volumio volumio[1167]: info: CoreStateMachine::getQueue Jan 11 11:32:44 volumio volumio[1167]: info: CorePlayQueue::getQueue Jan 11 11:32:44 volumio volumio[1167]: info: Preload queue cleared Jan 11 11:32:55 volumio volumio[1167]: info: Preload queue cleared Jan 11 11:32:55 volumio volumio[1167]: info: CoreCommandRouter::volumioReplaceandPlayItems Jan 11 11:32:55 volumio volumio[1167]: info: CoreStateMachine::ClearQueue Jan 11 11:32:55 volumio volumio[1167]: info: CoreStateMachine::stop Jan 11 11:32:55 volumio volumio[1167]: info: CoreStateMachine::serviceStop Jan 11 11:32:55 volumio volumio[1167]: info: Received STOP, but no service to execute it Jan 11 11:32:55 volumio volumio[1167]: info: CorePlayQueue::clearPlayQueue Jan 11 11:32:55 volumio volumio[1167]: info: CorePlayQueue::saveQueue Jan 11 11:32:55 volumio volumio[1167]: info: CoreCommandRouter::volumioPushQueue Jan 11 11:32:55 volumio volumio[1167]: info: CoreStateMachine::addQueueItems Jan 11 11:32:55 volumio volumio[1167]: info: CorePlayQueue::addQueueItems Jan 11 11:32:55 volumio volumio[1167]: info: Preload queue cleared Jan 11 11:32:55 volumio volumio[1167]: info: Adding Item to queue: artists://A%20Flock%20Of%20Seagulls Jan 11 11:32:55 volumio volumio[1167]: info: Exploding uri artists://A%20Flock%20Of%20Seagulls in service mpd Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioPushQueue Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::saveQueue Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::updateTrackBlock Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrackBlock Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: play , [object Object] Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioPlay Jan 11 11:32:56 volumio volumio[1167]: verbose: UNSET VOLATILE: Service: undefined Jan 11 11:32:56 volumio volumio[1167]: ------------------------------------ BT MESSAGE: [FUNC] detachBluetooth Jan 11 11:32:56 volumio volumio[1167]: ------------------------------------ BT MESSAGE: [FUNC] btAudioOutput Jan 11 11:32:56 volumio volumio[1167]: ------------------------------------ BT MESSAGE: [dbus-next] Disabling Bluetooth Audio Output Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::play index 0 Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 11:32:56 volumio volumio[1167]: ------------------------------------ BT MESSAGE: Bluetooth audio output disabled. Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::stop Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::resetVolumioState Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::getcurrentVolume Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::play index undefined Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioStop Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::stop Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::setConsumeUpdateService undefined Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::startPlaybackTimer Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:32:56 volumio volumio[1167]: verbose: ControllerMpd::clearAddPlayTracks NAS/Nas/Va/80s.Maxi.Hit.2013.WAV/Various Artists - 80s Maxi Hit Collection - The Rare 12-Inches (2013) WAV/CD3/03 - A Flock Of Seagulls - The More You Live,.wav Jan 11 11:32:56 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand stop Jan 11 11:32:56 volumio volumio[1167]: info: sendMpdCommand stop took 17 milliseconds Jan 11 11:32:56 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand clear Jan 11 11:32:56 volumio volumio[1167]: info: Jan 11 11:32:56 volumio volumio[1167]: ---------------------------- MPD announces system playlist update Jan 11 11:32:56 volumio volumio[1167]: info: Ignoring MPD Status Update Jan 11 11:32:56 volumio volumio[1167]: info: sendMpdCommand clear took 30 milliseconds Jan 11 11:32:56 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand add "NAS/Nas/Va/80s.Maxi.Hit.2013.WAV/Various Artists - 80s Maxi Hit Collection - The Rare 12-Inches (2013) WAV/CD3/03 - A Flock Of Seagulls - The More You Live,.wav" Jan 11 11:32:56 volumio volumio[1167]: error: updateQueue error: null Jan 11 11:32:56 volumio volumio[1167]: info: Jan 11 11:32:56 volumio volumio[1167]: ---------------------------- MPD announces system playlist update Jan 11 11:32:56 volumio volumio[1167]: info: Ignoring MPD Status Update Jan 11 11:32:56 volumio volumio[1167]: info: ------------------------------ 52ms Jan 11 11:32:56 volumio volumio[1167]: info: sendMpdCommand add "NAS/Nas/Va/80s.Maxi.Hit.2013.WAV/Various Artists - 80s Maxi Hit Collection - The Rare 12-Inches (2013) WAV/CD3/03 - A Flock Of Seagulls - The More You Live,.wav" took 47 milliseconds Jan 11 11:32:56 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand play Jan 11 11:32:56 volumio volumio[1167]: info: ------------------------------ 29ms Jan 11 11:32:56 volumio volumio[1167]: info: sendMpdCommand play took 24 milliseconds Jan 11 11:32:56 volumio volumio[1167]: info: VolumeController:: Volume=19 Mute =false Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:32:56 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:32:56 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::updateTrackBlock Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrackBlock Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioRetrievevolume Jan 11 11:32:56 volumio volumio[1167]: info: VolumeController:: Volume=19 Mute =false Jan 11 11:32:56 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:32:56 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:32:56 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:32:56 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:32:56 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:32:59 volumio volumio[1167]: info: Jan 11 11:32:59 volumio volumio[1167]: ---------------------------- MPD announces state update: player Jan 11 11:32:59 volumio volumio[1167]: info: ControllerMpd::getState Jan 11 11:32:59 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand status Jan 11 11:32:59 volumio volumio[1167]: info: Jan 11 11:32:59 volumio volumio[1167]: ---------------------------- MPD announces state update: player Jan 11 11:32:59 volumio volumio[1167]: info: sendMpdCommand status took 85 milliseconds Jan 11 11:32:59 volumio volumio[1167]: info: ControllerMpd::getState Jan 11 11:32:59 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand status Jan 11 11:32:59 volumio volumio[1167]: verbose: ControllerMpd::parseState Jan 11 11:32:59 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 11:32:59 volumio volumio[1167]: info: sendMpdCommand status took 15 milliseconds Jan 11 11:32:59 volumio volumio[1167]: info: sendMpdCommand playlistinfo took 11 milliseconds Jan 11 11:32:59 volumio volumio[1167]: verbose: ControllerMpd::parseState Jan 11 11:32:59 volumio volumio[1167]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jan 11 11:33:00 volumio volumio[1167]: verbose: ControllerMpd::parseTrackInfo Jan 11 11:33:00 volumio volumio[1167]: info: ControllerMpd::pushState Jan 11 11:33:00 volumio volumio[1167]: info: CoreCommandRouter::servicePushState Jan 11 11:33:00 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:00 volumio volumio[1167]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":251,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"The More You Live, The More You Love (7'' Remix)","artist":"A Flock Of Seagulls","album":"80s Maxi Hit Collection - The Rare 12-Inches","uri":"NAS/Nas/Va/80s.Maxi.Hit.2013.WAV/Various Artists - 80s Maxi Hit Collection - The Rare 12-Inches (2013) WAV/CD3/03 - A Flock Of Seagulls - The More You Live,.wav","trackType":"wav"} Jan 11 11:33:00 volumio volumio[1167]: verbose: CURRENT POSITION 0 Jan 11 11:33:00 volumio volumio[1167]: info: CoreStateMachine::syncState stateService play Jan 11 11:33:00 volumio volumio[1167]: info: CoreStateMachine::syncState currentStatus stop Jan 11 11:33:00 volumio volumio[1167]: info: ------------------------------ 131ms Jan 11 11:33:00 volumio volumio[1167]: info: sendMpdCommand playlistinfo took 49 milliseconds Jan 11 11:33:00 volumio volumio[1167]: verbose: ControllerMpd::parseTrackInfo Jan 11 11:33:00 volumio volumio[1167]: info: ControllerMpd::pushState Jan 11 11:33:00 volumio volumio[1167]: info: CoreCommandRouter::servicePushState Jan 11 11:33:00 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:00 volumio volumio[1167]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1214,"duration":251,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1411 Kbps","isStreaming":false,"title":"The More You Live, The More You Love (7'' Remix)","artist":"A Flock Of Seagulls","album":"80s Maxi Hit Collection - The Rare 12-Inches","uri":"NAS/Nas/Va/80s.Maxi.Hit.2013.WAV/Various Artists - 80s Maxi Hit Collection - The Rare 12-Inches (2013) WAV/CD3/03 - A Flock Of Seagulls - The More You Live,.wav","trackType":"wav"} Jan 11 11:33:00 volumio volumio[1167]: verbose: CURRENT POSITION 0 Jan 11 11:33:00 volumio volumio[1167]: info: CoreStateMachine::syncState stateService play Jan 11 11:33:00 volumio volumio[1167]: info: CoreStateMachine::syncState currentStatus play Jan 11 11:33:00 volumio volumio[1167]: info: Received an update from plugin. extracting info from payload Jan 11 11:33:00 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:33:00 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:00 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 11:33:00 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:33:00 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:33:00 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:33:00 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:33:00 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:00 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:33:00 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:00 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:33:00 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:33:00 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:33:00 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:33:00 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:00 volumio volumio[1167]: info: ------------------------------ 245ms Jan 11 11:33:04 volumio volumio[1167]: info: VolumeController::SetAlsaVolume40 Jan 11 11:33:04 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:33:04 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:04 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 11:33:04 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:33:04 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:33:04 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:33:04 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:33:04 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:06 volumio volumio[1167]: info: VolumeController::SetAlsaVolume50 Jan 11 11:33:06 volumio volumio[1167]: info: VolumeController::SetAlsaVolume60 Jan 11 11:33:06 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:33:06 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:06 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 11 11:33:06 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:33:06 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:33:06 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:33:06 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:33:06 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:06 volumio volumio[1167]: info: CoreStateMachine::pushState Jan 11 11:33:06 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:06 volumio volumio[1167]: info: CoreCommandRouter::volumioPushState Jan 11 11:33:06 volumio volumio[1167]: info: MRS: Pushing multiroomSync output update for this device Jan 11 11:33:06 volumio volumio[1167]: info: MRS: Pushing multiroomSync output Jan 11 11:33:06 volumio volumio[1167]: info: CoreCommandRouter::volumioGetState Jan 11 11:33:06 volumio volumio[1167]: info: CorePlayQueue::getTrack 0 Jan 11 11:33:25 volumio volumio[1167]: info: CoreCommandRouter::executeOnPlugin: multiroom , audioOutputPlay Jan 11 11:33:25 volumio volumio[1167]: info: Error : CoreCommandRouter::executeOnPlugin: No method [audioOutputPlay] in plugin multiroom Jan 11 11:33:25 volumio volumio[1167]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 11:33:26 volumio volumio[1167]: TypeError: Cannot read properties of undefined (reading 'then') Jan 11 11:33:26 volumio volumio[1167]: at outputs.audioOutputPlay (/volumio/app/plugins/audio_interface/outputs/index.js:367:9) Jan 11 11:33:26 volumio volumio[1167]: at CoreCommandRouter.audioOutputPlay (/volumio/app/index.js:2279:30) Jan 11 11:33:26 volumio volumio[1167]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1467:26) Jan 11 11:33:26 volumio volumio[1167]: at Socket.emit (node:events:514:28) Jan 11 11:33:26 volumio volumio[1167]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Jan 11 11:33:26 volumio volumio[1167]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Jan 11 11:33:26 volumio volumio[1167]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 11 11:33:27 volumio sudo[2912]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-11 11:32' Jan 11 11:33:27 volumio sudo[2912]: 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"