Getting rid of dependence on external utilities

[Magalex2x14]

Discussion in continuation of the topic raised here, and to accumulate knowledge about the methods of solving this issue.

As far as I understand, at the moment we use external utilities to solve the following tasks:

• getting a list of available hci-interfaces;
• reset interfaces in case of a problems;

At leisure, I decided to delve a little into this topic, and came across:

1. this python code that uses system calls to get information about all present hci-interfaces;
2. this code brings hci interface up and down and gets its info (bdaddr, for example) and current status using hci commands (easy to implement in ble_monitor);
   there are many useful links to sources of technical details inside the comments of the both sources.

The second code solves the problem of resetting the interface (and allows you to control the success of the operation), but I'm not sure about the first one, since it uses system calls, which may not be the right way (given the possible inclusion of integration in the official home-assistant repository). I see two alternatives - to use the Bluez DBus API to make requests to the bluetooth daemon, or using the second code to iterate over interface numbers in series until the first one is encountered, which will return an erroneous message in response to a hci_dev_info request :)

[Ernst79]

Hi @Magalex2x14 Magalex2x14, welcome back!

The way I have programmed it now is running some command line commands via the subprocess package.

subprocess.run(
        ["rfkill", "list", "bluetooth"], stdout=subprocess.PIPE, stderr=subprocess.PIPE, check=True
    )

I have limited time to look into this, but feel free to make a better proposal. I’m going to move to a new house, so can’t spend much time coming months.

[Magalex2x14]

Hi ) Also, unfortunately, I can not devote as much time to this as I would like. For now, I just wanted to share my findings. But the problem is interesting - I will deal with it as much as possible.

By the way, recently one of my old buddies contacted me when he saw a familiar nickname. He had a problem with the "Event loop stopped before future completed" error. According to the diagnostic result, it turned out that his bluetooth adapter (rpi 3b) turned off for some reason during operation (the status became DOWN). I feel that by resolving the issue of adapter state control, we will be one step closer to increasing the stability of the integration.

[Ernst79]

Yes, that could help probably. It’s a difficult error, and I still can’t find out why some people have these errors. It certainly seems related to the Bluetooth adapter, not running properly. Let’s just collect info in this topic and we will see how far we get.

[Ernst79]

I tried the 2nd code, I copies the code into the BLE monitor folder and added the following code in bt_helpers.py, just for some initial testing.

    for interface in interface_list:
        hci = BluetoothHCI(device_id=interface, auto_start=False)
        hci_info = hci.get_device_info()
        _LOGGER.error(hci_info)

It finds the HCI info nicely.

2022-01-30 21:35:50 ERROR (MainThread) [custom_components.ble_monitor.bt_helpers] {'id': 0, 'name': b'hci0', 'addr': '0:1a:7d:da:71:15'}
2022-01-30 21:35:50 ERROR (MainThread) [custom_components.ble_monitor.bt_helpers] {'id': 1, 'name': b'hci1', 'addr': 'b8:27:eb:77:75:50'}

The fist MAC looks a bit weird, with one 0 in the first byte of the MAC, but that's probably not a big issue to solve (should be 00).

But after that, it won't find my HCI adapter anymore.

2022-01-30 21:35:54 ERROR (MainThread) [custom_components.ble_monitor] Bluetooth adapter with MAC address ['00:1A:7D:DA:71:15'] was not found. It is therefore changed back to the default adapter. Check the BLE monitor settings, if needed. 

Not sure if that is related to the following requirement:

Before running a hcipy based script you should stop the bluetoothd system service (as it can interfer):

Something to figure out tomorrow...

[Magalex2x14]

Before running a hcipy based script you should stop the bluetoothd system service (as it can interfer):

It's curious. And anxious. I have been suspecting this daemon of being bad for a long time, and I always stop it at boot time :)

In this repository, I was interested in these lines.

I think like this:
In fact, to control the interface and obtain information about it, the HCI interface commands are used (the constants HCIDEVUP, HCIDEVDOWN, HCIGETDEVINFO, by analogy with how we start and stop scanning), and we already know how to do it. The task is only to early receive a response with the result of the HCIGETDEVINFO command execution. The correct solution, as I see it, is to include the procedure for obtaining information about interface in the aioblescan initialization code (similar to _handle_cc_le_read_local_supported_features, which is executed by the library immediately when connected to the hci interface, and we just need to extend the chain of initialization commands with the HCIGETDEVINFO command for obtaining information about the interface, and reset the self._uninitialized flag only thereafter). After that, it will only be necessary to initialize the instance of the BLEmonitor class at the very beginning of async_setup_entry, and execute a separate get_interface_info method, in which we can simply try to create a connection with hci interfaces, after which we will either have an error or a mac address. In addition, nothing prevents us from extending the functionality of aioblescan with commands to get up and down the interface.

P.S. By the way, I suddenly discovered that a hci reset command is already implemented in aioblescan...

[Ernst79]

Makes sense, yes.

[Magalex2x14]

A small investigation into the bank:

Examining the result of executing the Read Local Supported Commands during connection initialization with aioblescan on all three of my interfaces, I found the Read BD ADDR command:

A short googling gave the code for this command: ogf 0x04, ocf 0x0009

Successful attempt with hcitool:

root@mini2x14:/home/aleksey# hcitool -i hci1 cmd 0x04 0x0009
< HCI Command: ogf 0x04, ocf 0x0009, plen 0
> HCI Event: 0x0e plen 10
  01 09 10 00 11 71 DA 7D 1A 00

Relevant event in btmon output:

@ RAW Open: hcitool (privileged) version 2.22         
< HCI Command: Read BD ADDR (0x04|0x0009) plen 0      
> HCI Event: Command Complete (0x0e) plen 10     
      Read BD ADDR (0x04|0x0009) ncmd 1
        Status: Success (0x00)
        Address: 00:1A:7D:DA:71:11 (cyber-blue(HK)Ltd)
@ RAW Close: hcitool

In addition, there are no commands similar to HCIGETDEVINFO, HCIUP, HCIDOWN in the supported lists. There are no such commands here either - HCI commands. Reset is present, yes.
I can't find the end. I suspect the code in python-hcipy is making some kind of a system call. An attempt to catch these commands using btmon did not give anything - the corresponding events are absent in the btmon output:

@ RAW Open: python (privileged) version 2.22                                                                                                         {0x0007} 4.504650
@ RAW Close: python                                                                                                                                  {0x0007} 4.520882

In general, on the one hand, it s a success (we can get a mac address and reset the interface), on the other, even more questions...

We need to check if the "Event loop stopped before future completed" error always occurs when trying to start a new scan period (I'm pretty sure it is):

self._event_loop.run_until_complete(btctrl[hci].send_scan_request(self._active))

It seems to me that it never appeared in the cycle

self._event_loop.run_forever()

that is, during the actual collection of packets. Thus, it turns out that the event leading to the problem with starting a new scan occurs in the previous period. And since previous period is not interrupted, we have a chance to catch the corresponding event. It is possible to make a separate parser for them. At the initial stage, for example, we can log all events other than the LE Meta Event (0x3e), and in the future, upon the occurrence of certain events (such as Hardware error (0x10) or others identified as a result of collecting user statistics), we can set special flag and decide to reset the interface or user notification immediately after the end of the current period.

[Magalex2x14]

Also, I think it’s worth trying somehow to control the contents of the response to read_local_supported_features and read_local_supported_commands when establishing a connection with the interface (at this stage there are also no problems, if I’m not mistaken) - perhaps some answers will be contained there. Perhaps they will let us know are we are able to start a new scan period.

[Magalex2x14]

A small experiment - trying to turn off the adapter while ble_monitor is running to cause an error Event loop stopped:

btmgmt --index 1 power off

btmon:

@ MGMT Command: Set Powered (0x0005) plen 1                  {0x0007} 22:41:48.875507
        Powered: Disabled (0x00)
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2            #87 22:41:48.875565
        Scanning: Disabled (0x00)
        Filter duplicates: Disabled (0x00)
> HCI Event: Command Complete (0x0e) plen 4                       #88 22:41:48.888132
      LE Set Scan Enable (0x08|0x000c) ncmd 1
        Status: Success (0x00)
@ MGMT Event: Discovering (0x0013) plen 2                    {0x0007} 22:41:48.888270
        Address type: 0x00
        Discovery: Disabled (0x00)
@ MGMT Event: Command Complete (0x0001) plen 7               {0x0007} 22:41:48.888319
      Set Powered (0x0005) plen 4
        Status: Success (0x00)
        Current settings: 0x00000200
          Low Energy
= Close Index: 00:1A:7D:DA:71:11                                      22:41:48.888349
@ RAW Close: hass                                            {0x0004} 22:41:49.607698
@ RAW Open: hass (privileged) version 2.22                   {0x0004} 22:41:49.611150
@ RAW Close: hass                                            {0x0004} 22:41:49.612524

HA log:

2022-01-31 22:42:49 ERROR (Thread-3) [custom_components.ble_monitor] HCIdump thread: Runtime error while sending scan request on hci1: Event loop stopped before Future completed..

1. As I suggested above, the error occurred at 22:42:49, although the scan was actually interrupted by the interface stop at 22:41:48.
   It is noteworthy that before the interface is stopped, the scan disable command appeared with the corresponding response event - we can catch it.
2. The btmon output does not contain the aioblescan connection initialization commands (read_local_supported_features and etc), which are requested every time when starting a new period. This means that at the time of attempting to start scanning, the BLEScanRequester instance property self._uninitialized = True. We can check this flag before attempting to start scan.
3. Interface control commands appear with the label MGMT. In the BlueZ sources is stated that to control the interface, you need to select the HCI_CHANNEL_CONTROL channel in the socket properties - then all interface control commands will be accessible. It looks like it's possible to extend aioblescan's create_bt_socket routine to open a control channel.

[Magalex2x14]

With point number two there is a difficulty - in fact, the _uninitialized flag is not yet resetted before starting the scan 99% of the time...

[Magalex2x14]

The problem with point 2 is solved - below is my experiment with aioblescan initialization status control. The send_scan_request is skipped on the problematic interface, and a corresponding entry is made in the log. The code is working, I checked it by turning off and on the interface while ble_monitor was running. Accordingly, this interface is also skipped when scanning must be stopped at the end of the period.

            if "disable" not in self.config[CONF_BT_INTERFACE]:
                for hci in self._interfaces:
                    try:
                        mysocket[hci] = aiobs.create_bt_socket(hci)
                    except OSError as error:
                        _LOGGER.error("HCIdump thread: OS error (hci%i): %s", hci, error)
                    else:
                        fac[hci] = getattr(
                            self._event_loop, "_create_connection_transport"
                        )(mysocket[hci], aiobs.BLEScanRequester, None, None)
                        conn[hci], btctrl[hci] = self._event_loop.run_until_complete(
                            fac[hci]
                        )
                        
                        btctrl[hci].process = self.process_hci_events
                        
                        # Wait up to five seconds for aioblescan to initialize
                        initialized_evt = getattr(btctrl[hci], "_initialized")
                        
                        try:
                            self._event_loop.run_until_complete(asyncio.wait_for(initialized_evt.wait(), 5))
                        except asyncio.TimeoutError:
                            interface_is_ok[hci] = False
                            _LOGGER.error("HCIdump thread: something wrong - interface hci%i not ready! Skipping it for current period.", hci)
                            continue
                        
                        _LOGGER.debug("HCIdump thread: connected to hci%i", hci)
                        
                        try:
                            self._event_loop.run_until_complete(
                                btctrl[hci].send_scan_request(self._active)
                            )
                            interface_is_ok[hci] = True
                        except RuntimeError as error:
                            if self.config[CONF_BT_AUTO_RESTART] is True:
                                ts_now = dt_util.now()
                                if (ts_now - self.last_bt_reset).seconds > 60:
                                    _LOGGER.error(
                                        "HCIdump thread: Runtime error while sending scan request on hci%i: %s. "
                                        "Resetting Bluetooth adapter %s and trying again.",
                                        hci,
                                        error,
                                        BT_INTERFACES[hci],
                                    )
                                    reset_bluetooth(hci)
                                    self.last_bt_reset = ts_now
                            else:
                                _LOGGER.error(
                                    "HCIdump thread: Runtime error while sending scan request on hci%i: %s.",
                                    hci,
                                    error,
                                )
            _LOGGER.debug("HCIdump thread: start main event_loop")
            try:
                self._event_loop.run_forever()
            finally:
                _LOGGER.debug("HCIdump thread: main event_loop stopped, finishing")
                if "disable" not in self.config[CONF_BT_INTERFACE]:
                    for hci in self._interfaces:
                        if interface_is_ok[hci] is False:
                            continue
                        try:
                            self._event_loop.run_until_complete(
                                btctrl[hci].stop_scan_request()
                            )
                        except RuntimeError as error:

We can also skip the stop_scan_request with the current approach with the RuntimeError interception, yes, but personally I would be more comfortable with the code above... The current approach does not wait for initialization - I do not exclude that some of the problems with "Event loop stopped before future completed" may be related with this. That is, the question is - is it possible that this error can occur due to the fact that at the time the scan is started, initialization has not yet been completed?

[Magalex2x14]

@Ernst79 I seem to have found the root of the problem with Event loop stopped before future completed.

I made a small program with the BLEmonitor and HCIdump classes (slightly modified to run outside of HA):

print("Init")
blemonitor = BLEmonitor(None)
print("blemonitor.start()")
blemonitor.start()
time.sleep(10)
print("blemonitor.restart()")
blemonitor.restart()
time.sleep(10)
print("blemonitor.stop()")
blemonitor.stop()

It turned out that the error always occurs when the scan is restarted (blemonitor.restart()), and does not occur at the start of the first period. Also, after blemonitor.stop() the program does not exit (the HCIdump thread hangs).

As far as I understand, the problem lies in the fact that when event loop must be stopped to restart scanning at the end of the period the attempt to send a scan request has not yet completed, because aioblescan is still pending initialization, because there is no response from the interface about the supported commands and features (aioblescan needs to know whether it is asking for a legacy scan or an extended one):


Accordingly, the system tells us that we are stopping the event loop with an unfinished feature )

There is no choice - we need to check the initialization status of aioblescan. Catching an error in this case is not enough, since there is a negative effect in the form of a feature and a thread stuck. I think ideally the timeout should be implemented in aioblescan.
For the time being, I propose to start with a check as in my comment above. Later I will prepare a pull request (I need to restore the development environment - I recently reinstalled the system). After that I will try to take the interfaces management task.

[Ernst79]

Wow, you really dived into it. Great that you post all your steps here, helps me to understand and follow what you do and what you try.

[Magalex2x14]

Working example using BlueZ DBus API (bluetooth daemon should be running):

import dbus

bus = dbus.SystemBus()

manager = dbus.Interface(bus.get_object("org.bluez", "/"), "org.freedesktop.DBus.ObjectManager")
managed_objects = manager.GetManagedObjects()
for path, iface in managed_objects.items():
    if ("hci" in path and "org.bluez.Adapter1" in iface and "org.freedesktop.DBus.Properties" in iface):
        hci_props = dbus.Interface(bus.get_object("org.bluez", path), "org.freedesktop.DBus.Properties")
        print(hci_props.Get("org.bluez.Adapter1", "Address"))
        print(hci_props.Get("org.bluez.Adapter1", "Powered"))
        if hci_props.Get("org.bluez.Adapter1", "Address") == "00:1A:7D:DA:71:11":
            hci_props.Set("org.bluez.Adapter1", "Powered", True)
            print(hci_props.Get("org.bluez.Adapter1", "Powered"))

However, the python-dbus library fails to install in the official HassOS image.

Found in my bookmarks excellent exhaustive materials from @ukBaz - one and two.
After reading them, I decided to use the PyGObject approach, but this thing didn’t install either )
Installed the dasbus lib, but it did not work, there was an error during import...

As a result, I settled on pydbus, although it has not been updated for a long time, and many consider it abandonware.
The only alternative is a hard low-level work with the hci interface, as implemented in hcipy (as far as I understand, due to a bug in python sockets, we can't access the Bluez MGMT socket yet, @ukBaz also mentions it).

So, here is working example for pydbus:

from pydbus import SystemBus

BUS_NAME = 'org.bluez'
OBJ_MANAGER = 'org.freedesktop.DBus.ObjectManager'

bus = SystemBus()

btadaptermac = "00:1A:7D:DA:71:11"
bluez = bus.get(BUS_NAME, '/')
manager = bluez[OBJ_MANAGER]
managed_objects = manager.GetManagedObjects()
for path, iface in managed_objects.items():
    if "hci" in path:
        print(path)
        adapter = bus.get(BUS_NAME, path)
        print(f'{adapter.AddressType} address: {adapter.Address}, powered = {adapter.Powered}')

        if adapter.Address == btadaptermac:

            # change to False to power off
            adapter.Powered = True
            print(f'{adapter.AddressType} address: {adapter.Address}, powered = {adapter.Powered}')

[ukBaz]

Thanks for tagging me in this chat. Good to know that what I've written is being read by someone. :-)

This is a long thread so haven't had chance to read it all. If you have some specific things you are trying to do with BlueZ D-Bus API then let me know and I'll help if I can.

[Magalex2x14]

Due to the fact that we are forced to support a platform on which the rights and capabilities of the user are very limited, I settled on working through pydbus (this is the only thing that worked on this platform without troubles).

The topic is interesting, we are new to it, and I will definitely let you know if there are new tasks, thanks. Thanks again for posting your experience - it helped a lot!

[Magalex2x14]

@Ernst79 Do you remember what for rfkill was added to the reset procedure? Were there situations when bluetooth was blocked?

[Magalex2x14]

Is there a need for it? If there really is, then I think that this functionality is also can be implemented through DBus...

[Magalex2x14]

https://github.com/wraith-wireless/PyRIC/blob/master/pyric/utils/rfkill.py
https://github.com/norbusan/rfkill-applet/blob/master/rfkill-sys.py

on the second link the code using both approaches - /dev/rfkill and DBus. However, I do not have org.freedesktop.Hal present in my system (I suspect that the service required for this is part of the desktop environment).
So... PyRIC looks good, and successfully installed on HassOS:

Python 3.9.2 (default, Feb 28 2021, 17:03:44)
[GCC 10.2.1 20210110] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import pyric.utils.rfkill as rfkill
>>> rfkill.rfkill_list()
{'hci0': {'idx': 0, 'type': 'bluetooth', 'soft': False, 'hard': False}, 'hci1': {'idx': 1, 'type': 'bluetooth', 'soft': False, 'hard': False}, 'hci2': {'idx': 2, 'type': 'bluetooth', 'soft': False, 'hard': False}}
>>> rfkill.soft_blocked(1)
False
>>> rfkill.hard_blocked(1)
False
>>>

[Ernst79]

I’m not sure there actually were situations where rfkill was needed, we have to check #295 for that.

[Magalex2x14]

Checked out the thread, and didn't see the actual rfkill work, yes. Since rfkill_unblock_bluetooth() in the bt_helpers code is run after bluetoothctl_power_on(), then a blocked adapter would simply not turn on, I think. I suggest leaving the blocked status check, reporting if the adapter is blocked, and do not try to turn it off / on. The essence of rfkill is to control the state of radio interface hardware switches and their emulation (soft block), as I see it.

[Ernst79]

That's sounds ok.

I found a small bug, on my main machine, after the update to 7.5.0. Didn't had time yet to look into it. It continues to run, so not a big issue right away.

Logger: root
Source: custom_components/ble_monitor/__init__.py:704
Integration: Passive BLE monitor ([documentation](https://github.com/custom-components/ble_monitor), [issues](https://github.com/custom-components/ble_monitor/issues))
First occurred: 11:52:03 (101 occurrences)
Last logged: 13:32:57

Uncaught thread exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/threading.py", line 973, in _bootstrap_inner
    self.run()
  File "/config/custom_components/ble_monitor/__init__.py", line 704, in run
    if (self.config[CONF_BT_AUTO_RESTART] is True) and (interface_is_ok[hci] is False):
KeyError: 'bt_auto_restart'

[Magalex2x14]

Houston, we have a problem!

I don’t know how I checked the installation of the pydbus module on Homeassistant OS, but it is not work for me now either:

Setup failed for ble_monitor: Unable to import component: No module named 'gi'

Crap! Apparently, I messed up something (maybe I only checked on my HA core installation on Debian)...
The essence of the problem is the lack of a package in the HomeassistantOS distribution, which can be called as python-gi, python-gobject or pygobject. The PyGObject module is also fails to install. It looks like the gstreamer integration also has a similar problem.

In general, the new_bt_helpers branch contains untested code using pydbus (and rfkill using pyric).
I see two ways:

1. Communicate with developers and ask them to include python-gi, python-gobject or pygobject in the distribution and have difficulty supporting various versions of Homeassistant OS.
2. Look for a way to low-level work with the hci-interface directly (MGMT socket or try hcipy approach)...
3. Leave it as is...

Perhaps I'll move towards point number 2.

P.S. more observations: the HA Supervisor uses DBus, but the search over Core code does not give any results...

[Magalex2x14]

Wow! python-btsocket lib by ukBaz looks awesome (MGMT socket) , and works on HomeassistantOS.
I'm even glad that it didn't work out with DBus :)

[Magalex2x14]

https://github.com/ukBaz/python-btsocket

[Magalex2x14]

The next step after #703 I'm thinking of disabling all adapter functions except for LE at the start of integration. I see this as an option similar to restarting the interface. But later.