ukBaz / python-bluezero

A simple Python interface to Bluez
MIT License
396 stars 112 forks source link

Not consistently recognizing ibeacons #415

Open furgerf opened 2 months ago

furgerf commented 2 months ago

Hi, I'd like to detect ibeacons with a raspi and ideally range with them. For testing, I'm using two identical beacons, but I'm encountering some issues. Maybe you can help me understand what I'm doing wrong 🙂

Maybe first off - ranging doesn't seem to be implemented here, is there some limitation or is it just a matter of time/priority?

Regardless, I thought I'd start with just reading out some rssi values, to at least get a broad feeling for beacon proximity: using Scanner.start_beacon_scan(on_ibeacon=...) normally works, but I only get an initial callback invocation, presumably because it's only called on new devices. By the looks of it, that's what Scanner.clean_beacons is intended for, so I'm calling that every 10s, expecting to get a new rssi every 10s. (The beacons are configured to advertise every 1s.)

Now, my main issue is that I'm not consistently seeing the beacons. It seems they start disappearing (not re-appearing after cleaning) after running for a while. I verified that the same device still receives advertisements from the beacons (visible in bluetoothctl devices) and I also see them on my smartphone with nRF connect. I'm not quite sure when/why the beacons disappear, but I'm seeing two errors in the logs.

The first seems to be a race condition in the observer (an advertisement is received while determining devices to remove) - if you want I can submit a patch with some locking:

2024-09-06T09:27:53Z: Traceback (most recent call last):
2024-09-06T09:27:53Z:   File "x/app/bluetooth/bluetooth_server.py", line 102, in reset_beacons
2024-09-06T09:27:53Z:     Scanner.clean_beacons()
2024-09-06T09:27:53Z:   File "x/lib/python3.11/site-packages/bluezero/observer.py", line 62, in clean_beacons
2024-09-06T09:27:53Z:     for rm_dev in cls.remove_list:
2024-09-06T09:27:53Z: RuntimeError: Set changed size during iteration

I "feel like" I've been getting that one more frequently a few days ago (but not so much anymore), so I had also experimented with Scanner.stop_scan and adapter.quit.

The other error still pops up frequently, though not regularly - sometimes it appears several times a few seconds apart, sometimes not for a while. Not sure if it's related to beacons not showing up, since it doesn't necessarily seem to correlate.

2024-09-06T09:28:16Z: 2024-09-06 09:28:16,799 ERROR dbus.connection maybe_handle_message:222: Exception in handler for D-Bus signal:
2024-09-06T09:28:16Z: Traceback (most recent call last):
2024-09-06T09:28:16Z:   File "x/lib/python3.11/site-packages/dbus/connection.py", line 218, in maybe_handle_message
2024-09-06T09:28:16Z:     self._handler(*args, **kwargs)
2024-09-06T09:28:16Z:   File "x/lib/python3.11/site-packages/bluezero/adapter.py", line 314, in _interfaces_added
2024-09-06T09:28:16Z:     new_dev = device.Device(
2024-09-06T09:28:16Z:               ^^^^^^^^^^^^^^
2024-09-06T09:28:16Z:   File "x/lib/python3.11/site-packages/bluezero/device.py", line 53, in __init__
2024-09-06T09:28:16Z:     raise ValueError("Cannot find a device: " + device_addr +
2024-09-06T09:28:16Z: ValueError: Cannot find a device: XX:XX:XX:XX:XX:XX using adapter: YY:YY:YY:YY:YY:YY

Thanks in advance!

ukBaz commented 2 months ago

OK, there is a lot to unpack here...

At the core of the issue is that BlueZ doesn't want to flood the D-Bus with every single advertisement from every device. And in most situations this the correct thing to do. So BlueZ and the Linux kernel deliberately filter repeated advertisements from the same device.

BlueZ has SetDiscoveryFilter({'DuplicateData': True}) which is meant to show every advertisement from a device during Device Discovery if it contains ManufacturerData and/or ServiceData (i.e. it is likely to be a beacon) irrespective of whether the device have been discovered previously or not.

On Bluezero this is accessed with show_duplicates https://github.com/ukBaz/python-bluezero/blob/e1202855bf25ee145d5bd6941afddcda88998808/bluezero/adapter.py#L230-L237

However, there was/is also filtering done by the Linux kernel which meant that advertisements would still be missed. As a workaround to this I implemented clean_beacons which deletes a "beacon" after it has been discovered and processed. This tricked BlueZ and the Linux kernel in to believing it was always discovering a new beacon and no filtering took place.

This means that you should never need to call clean_beacon as on_device_found is already taking care of it. So my speculation is that the race condition is being caused by you calling clean_beacon.

If you are only seeing one advertisement from your iBeacon, have you set logging to debug to see if the device is being "cleaned" after it has been processed? I thinking something like:

import logging
from bluezero import observer

def print_ibeacon_range(data):
    print(f'iBeacon data: {data.major}-{data.minor} @ {data.rssi} [{data.tx_pwer}]')

def main():
    observer.start_beacon_scan(on_ibeacon=print_ibeacon_range)

if __name__ == '__main__':
    observer.logger.setLevel(logging.DEBUG)
    main()

Implementing a range calculation is bit like saying there should only be one programming language. Which ever one I choose, it would be the wrong one for people depending on what they were trying to do. As a result Bluezero has not implemented a range calculation.

I'm not sure where you are on this, but if you need an introduction then take a look at: http://www.davidgyoungtech.com/2020/05/15/how-far-can-you-go

furgerf commented 2 months ago

That's great, thanks for your explanations!

At the core of the issue is that BlueZ doesn't want to flood the D-Bus with every single advertisement from every device. And in most situations this the correct thing to do. So BlueZ and the Linux kernel deliberately filter repeated advertisements from the same device.

BlueZ has SetDiscoveryFilter({'DuplicateData': True}) which is meant to show every advertisement from a device during Device Discovery if it contains ManufacturerData and/or ServiceData (i.e. it is likely to be a beacon) irrespective of whether the device have been discovered previously or not.

On Bluezero this is accessed with show_duplicates

Ok, that should've already been taken care of since I'm calling Scanner.start_beacon_scan 👍

However, there was/is also filtering done by the Linux kernel which meant that advertisements would still be missed. As a workaround to this I implemented clean_beacons which deletes a "beacon" after it has been discovered and processed. This tricked BlueZ and the Linux kernel in to believing it was always discovering a new beacon and no filtering took place.

This means that you should never need to call clean_beacon as on_device_found is already taking care of it. So my speculation is that the race condition is being caused by you calling clean_beacon.

Yes - now I see that too, that makes sense.

If you are only seeing one advertisement from your iBeacon, have you set logging to debug to see if the device is being "cleaned" after it has been processed?

The device seems to get removed repeatedly, but the callback doesn't necessarily get invoked - shouldn't the device only get removed once until it's re-discovered? I'm also surprised that there are periods of several minutes where the device doesn't get removed - do you have an idea why?

2024-09-11 12:38:15,282 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:38:15,282 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:38:38,148 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:38:38,148 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:38:39,931 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:38:39,931 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:38:49,411 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:38:49,411 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:42:18,762 - bluezero.observer - INFO - iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -40
2024-09-11 12:42:18,762 INFO bluezero.observer process_ibeacon:145: iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -40
2024-09-11 12:42:18,763 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:42:18,763 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:44:53,971 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:44:53,971 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:45:03,199 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:45:03,199 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:45:05,059 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:45:05,059 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:49:28,241 - bluezero.observer - INFO - iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -40
2024-09-11 12:49:28,241 INFO bluezero.observer process_ibeacon:145: iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -40
2024-09-11 12:49:28,242 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:49:28,242 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:51:18,624 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:51:18,624 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:20,624 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:20,624 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:39,716 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:39,716 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:50,945 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:50,945 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:02:32,171 - bluezero.observer - INFO - iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -46
2024-09-11 13:02:32,171 INFO bluezero.observer process_ibeacon:145: iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -46
2024-09-11 13:02:32,171 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:02:32,171 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:04:55,057 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:04:55,057 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:06:48,384 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:06:48,384 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:07:24,550 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:07:24,550 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:07:35,288 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:07:35,288 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:08:02,912 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:08:02,912 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:08:05,067 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:08:05,067 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX

Implementing a range calculation is bit like saying there should only be one programming language. Which ever one I choose, it would be the wrong one for people depending on what they were trying to do. As a result Bluezero has not implemented a range calculation.

Thanks, that makes sense. I think I've seen that iOS implements ranging functionality, hence the question.

ukBaz commented 2 months ago

I am not sure I fully understand what the logging output is telling me so time for me to share some theories and maybe you can prove (or disprove) them.

Firstly, it seems like there are two entries per logging event. e.g.

2024-09-11 12:42:18,762 - bluezero.observer - INFO - iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -40
2024-09-11 12:42:18,762 INFO bluezero.observer process_ibeacon:145: iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -40

I suspect this is because Bluezero has tools.create_module_logger helper function which sets up a logging handler and you are setting up another logging handler with a slightly different format. Then both handlers are outputting. In hindsight, Bluezero is probably doing the wrong thing by setting this up, but the intention was good. Anyway, the result of this is that we are seeing double the amount of entries we should.

If I remove these duplicates and focus on logging from one process_ibeacon to the next there is:

2024-09-11 12:49:28,241 INFO bluezero.observer process_ibeacon:145: iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -40
2024-09-11 12:49:28,242 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 12:51:18,624 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:20,624 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:39,716 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:00:50,945 DEBUG bluezero.observer clean_beacons:63: Remove /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX
2024-09-11 13:02:32,171 INFO bluezero.observer process_ibeacon:145: iBeacon: 11111111-1111-1111-1111-111111111111 - 7 - 3  ↗ -75 ↘ -46

It does seem odd that it is getting removed 5 times for a single discovery. We probably need to do some more debug as to why this is. I'm assuming /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX is all the same device and you are not discovering other beacons which are being removed. Is that a correct assumption? My theory is that the ibeacon device is getting discovered and added to remove_list in on_device_found too many times. Or the remove_list is not getting managed correctly in clean_beacons. Can you do some further debug to better identify where the issue might lay?

The time step between the add and remove is close together and what I would expect. However, the other gaps are massive in comparison. When running your script have separate terminals open with the following running to get more debug information:

bluetoothctl
sudo busctl monitor org.bluez
sudo btmon -t

bluetoothctl will tell you what BlueZ is seeing. I'm expecting to see it discover a device and then delete a device. If you typed devices at the prompt your ibeacon shouldn't be in the list.

busctl will show what is happening on the D-Bus. The main thing to look for here is the signal to say a device has been discovered.

btmon is the low level bluetooth information. This will be very verbose, but we are looking for discovery of your ibeacon. You are looking for timestamp of those discoveries compared to the timestamp in the logging output of process_ibeacon or clean_beacon

furgerf commented 2 months ago

I'm assuming /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX is all the same device and you are not discovering other beacons which are being removed. Is that a correct assumption?

Yes it's the same device. There's no other beacon (but many other bluetooth devices, many of them peripherals).

I did some testing - I believe I mentioned before that it seems to get worse after running for a while, until the next reboot, so I rebooted first for a "clean slate". Unfortunately I can't run btmon as it's running on ubuntu core and that seems to require some extra permissions - and busctl outputs around 200k lines per second, which seems pretty extreme. But I think just bluetoothctl is already helpful.

With bluetoothctl I see the following repeating sequence:

When "it gets worse", the time increases before the device is removed on bluetoothctl and CHG entries with RSSI, ServiceData Key/Value and AdvertisingFlags pop up.

To me this looks like there are two (maybe separate) issues:

Is it possible that (especially) the first issue is related to the very chatty dbus? Or could that also be caused by the second issue somehow?

ukBaz commented 2 months ago

OK, I think I've been able to reproduce multiple removes for a single discovery. This is what I got:

2024-09-13 05:46:36,998 - bluezero.observer - DEBUG - Device found: /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-13 05:46:37,006 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -81
2024-09-13 05:46:37,006 - bluezero.observer - DEBUG - For removal: {'/org/bluez/hci0/dev_3B_67_70_A3_68_76'}
2024-09-13 05:46:37,007 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-13 05:46:37,096 - bluezero.observer - DEBUG - Device found: /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-13 05:46:37,099 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -87
2024-09-13 05:46:37,099 - bluezero.observer - DEBUG - For removal: {'/org/bluez/hci0/dev_3B_67_70_A3_68_76'}
* 2024-09-13 05:46:37,099 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-13 05:46:37,134 - bluezero.observer - DEBUG - Device found: /org/bluez/hci0/dev_77_5A_90_8C_73_D2
2024-09-13 05:46:37,138 - bluezero.observer - DEBUG - For removal: {'/org/bluez/hci0/dev_3B_67_70_A3_68_76'}
* 2024-09-13 05:46:37,138 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-13 05:46:37,295 - bluezero.observer - DEBUG - Device found: /org/bluez/hci0/dev_1F_14_77_4C_C6_82
2024-09-13 05:46:37,299 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -84
2024-09-13 05:46:37,299 - bluezero.observer - DEBUG - For removal: {'/org/bluez/hci0/dev_1F_14_77_4C_C6_82'}
2024-09-13 05:46:37,299 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_1F_14_77_4C_C6_82
2024-09-13 05:46:37,634 - bluezero.observer - DEBUG - Device found: /org/bluez/hci0/dev_76_15_58_D0_2C_FE
2024-09-13 05:46:37,637 - bluezero.observer - DEBUG - For removal: {'/org/bluez/hci0/dev_1F_14_77_4C_C6_82'}
2024-09-13 05:46:37,637 - bluezero.observer - DEBUG - Remove /org/bluez/hci0/dev_1F_14_77_4C_C6_82

on_device_found is asynchronous and is executed every time D-Bus sends an InterfacesAdded signal because a new device is discovered. I think what I'm seeing is that when another device is discovered before the remove_list is tidied up is where there are multiple removes.

It seems like a more sophisticated scheme is required to remove the device once it has been processed.

Although I guess this doesn't address your main issues, which is you are not seeing all the updates from the beacon.

I'm not quite sure where to go with this... any thoughts?

ukBaz commented 2 months ago

It dawned on me that there should not be a class variable with a set tracking the devices to be removed. on_device_found should do the clean up (if required) at the end, only on the device that was discovered in that invocation of the callback.

I have created a new branch with a fix that works for me. Can you take a look and let me know if it works for you also. https://github.com/ukBaz/python-bluezero/tree/clean_beacons

By fix, I mean that I see frequent updates of the ibeacons RSSI and the "deletes" match the "founds".

e.g.

2024-09-14 04:17:19,588 - bluezero.observer - DEBUG - Found device: /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-14 04:17:19,594 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -83
2024-09-14 04:17:19,595 - bluezero.observer - DEBUG - Removing device /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-14 04:17:20,207 - bluezero.observer - DEBUG - Found device: /org/bluez/hci0/dev_E3_0C_2F_2C_09_92
2024-09-14 04:17:20,630 - bluezero.observer - DEBUG - Found device: /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-14 04:17:20,634 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -83
2024-09-14 04:17:20,635 - bluezero.observer - DEBUG - Removing device /org/bluez/hci0/dev_3B_67_70_A3_68_76
2024-09-14 04:17:20,773 - bluezero.observer - DEBUG - Found device: /org/bluez/hci0/dev_D5_78_BA_ED_35_DC
2024-09-14 04:17:20,878 - bluezero.observer - DEBUG - Found device: /org/bluez/hci0/dev_1F_14_77_4C_C6_82
2024-09-14 04:17:20,881 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -85
2024-09-14 04:17:20,881 - bluezero.observer - DEBUG - Removing device /org/bluez/hci0/dev_1F_14_77_4C_C6_82
2024-09-14 04:17:21,197 - bluezero.observer - DEBUG - Found device: /org/bluez/hci0/dev_1F_14_77_4C_C6_82
2024-09-14 04:17:21,200 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -83
2024-09-14 04:17:21,200 - bluezero.observer - DEBUG - Removing device /org/bluez/hci0/dev_1F_14_77_4C_C6_82
2024-09-14 04:17:21,453 - bluezero.observer - DEBUG - Found device: /org/bluez/hci0/dev_1F_14_77_4C_C6_82
2024-09-14 04:17:21,457 - bluezero.observer - INFO - iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0  ↗ -55 ↘ -83
2024-09-14 04:17:21,458 - bluezero.observer - DEBUG - Removing device /org/bluez/hci0/dev_1F_14_77_4C_C6_82

Any thoughts or comments welcome.

furgerf commented 2 months ago

Nice, thank you, that looks reasonable. I'm happy to give that a try, but I most likely won't get to it over the weekend.

Do you maybe have an idea what I might try work around my other issue with not getting the updates? E.g. like resetting something around bluez/serial or maybe dbus? That also might give some clue about where the problem is.

ukBaz commented 2 months ago

Do you maybe have an idea what I might try work around my other issue with not getting the updates? E.g. like resetting something around bluez/serial or maybe dbus? That also might give some clue about where the problem is.

Difficult to speculate on this without knowing which step is filtering out the updates. There several layers that it goes through. Starting at the bottom and working up.

Use btmon to see if the low-level discovery is happening of the ibeacon.

Use busctl monitor to see if the ibeacon is being put on the D-Bus as a PropertiesChanged or InterfacesAdded signal. The Bluezero python code is assuming InterfacesAdded. If it is PropertiesChanged it is likely that the list of devices in bluetoothctl. Try deleting it from the list in bluetoothctl.

Then finally, is making it through to on_device_found in the observer code?

furgerf commented 2 months ago

First off - great, the fix for device removal works for me. I didn't notice multiple removals for the same device :+1:

About the lack of discovery, I saw that I receive indeed PropertiesChanged (the CHG mentioned before) instead of NEW after some time, though I don't actually see InterfacesAdded with the device's path. When I see NEW in bluetoothctl, I see this in busctl:

‣ Type=method_call  Endian=l  Flags=0  Version=1  Priority=0 Cookie=4865
  Sender=:1.95  Destination=:1.93  Path=/org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX  Interface=org.freedesktop.DBus.Introspectable  Member=Introspect
  UniqueName=:1.95
  MESSAGE "" {
--

‣ Type=method_call  Endian=l  Flags=0  Version=1  Priority=0 Cookie=4866
  Sender=:1.95  Destination=:1.93  Path=/org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX  Interface=org.freedesktop.DBus.Properties  Member=Get
  UniqueName=:1.95
  MESSAGE "ss" {

There are multiple such Get entries after a single Introspect. What could make these messages change after running for a while?


Manually removing the device (bluetoothctl -- remove <device>) didn't work unfortunately. The device was added again but didn't propagate to bluezero - I see NEW in bluetoothctl, but not a corresponding InterfacesAdded with busctl. That surprised me, I expected that the former implies the latter.


Earlier I was rebooting the device to "fix" it. I tested some more there, just restarting bluetooth works too (since it's Ubuntu Core I'm restarting snap.bluez.bluez.service which I think would otherwise be bluetooth.service). I also found that bluetoothctl -- power off; bluetoothctl -- power on; bluetoothctl -- scan on seems to work (but only with scan on, and also the power off/on seems to be needed), although I didn't have that running for so long. Still, I tried to replicate that with bluezero as follows:

adapter.powered = False
adapter.powered = True
adapter.start_discovery()

I execute that every minute, but that doesn't really work - from what I can tell, this gets me into yet another "state" 😅

In the ideal case (e.g. after restarting the bluetooth service), I see something like this with bluetoothctl - which gets picked up nicely by bluezero:

[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon

In my original "bad state", I see this:

[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -71
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -58
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -58
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -69
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -71

With my attempt at restarting scanning with the snippet above, I see a mixture of NEW/DEL as well as CHG, but only with RSSI - the CHG appear when restarting scanning, RSSI changes so I assume advertisements are still received from the beacon:

[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -36
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -36
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -36
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -39
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[DEL] Device XX:XX:XX:XX:XX:XX iBeacon
[NEW] Device XX:XX:XX:XX:XX:XX iBeacon
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -39

This all leaves me more confused, rather than less... do you have other suggestions/tests that I could try? Is there a way I could get those RSSI changes?

ukBaz commented 2 months ago

OK, there is a lot to unpack there, with a lot of options on what we can try. Let me see if I can do this in a clear and concise way....

the fix for device removal works for me

Excellent! Thank you for testing.

In blutoothctl when you want to delete a device manually, I would suggest you don't have your Bluezero script running and that you ensure that discovery is off (scan off) before you delete the device. Then start your Bluezero script so you know that you don't have the beacon in the list before it starts discovery.

D-Bus has two signals. 1) InterfacesAdded for when a new device is discovered. 2) PropertiesChanged for when a device's information is updated.

The InterfacesAdded is always to interface 'org.freedesktop.DBus.ObjectManager' and D-Bus path /.

While to get the RSSI property change of the device you would need to connect to the signal on the org.bluez.Device1 interface but the path will be /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX where that path will be constantly changing for privacy.

So it is possible to work on the [CHG] but it is all a bit tricky to manage. This is why I would like to understand what is different about your setup. In bluetoothctl if you do show what does it show. I think the key entries are:

        Powered: yes
        Discovering: no

If you are going to stop and start things, I would stop discovery before powering off. e.g.

adapter.stop_discovery()
adapter.powered = False
adapter.powered = True
adapter.start_discovery()

I execute that every minute

How are you executing this every minute? Are you using https://github.com/ukBaz/python-bluezero/blob/e1202855bf25ee145d5bd6941afddcda88998808/bluezero/async_tools.py#L14-L27 ?

If you want a delay between powering off and back on, then split the above in to two callbacks. With the "off" callback calling the "on" callback. E.g. async_tools.add_timer_seconds(5, on_callback)

furgerf commented 2 months ago

Thanks for the suggestions - unfortunately, I couldn't get it to work reliably with scan off in bluetoothctl or stop_discovery() in bluezero. Thanks also for the explanation about the D-Bus signals - I'll skip the CHG then 🙂 I did more testing and reading, and have more questions if you don't mind 😅

I was thinking about that even in the "good state", I only get an update once every ~11s, while I see updates every second on the phone (which corresponds to the configured beacon advertisement interval). From your initial answer, I learned that there are different reasons why one wouldn't see all advertisements in bluezero. But it's not quite clear to me yet, with show_duplicates and the device removal by bluezero after discovery, wouldn't you expect to receive all advertisements or is there still more throttling somewhere?

I wanted to mess around with bluetoothctl/btmgmt directly and stopped resetting with bluezero (I was resetting every minute with a (synchronous) thread - did you ask because running it on the adapter's mainloop would prevent threading issues? I'll keep that in mind for next time.). What's left is scanning with bluezero (and yes: the adapter is powered and discovering). I then saw that btmgmt outputs the following while the scan is running:

hci0 type 7 discovering off
hci0 type 7 discovering on
hci0 type 7 discovering off
hci0 type 7 discovering on
hci0 type 7 discovering off

When I scan using bluetoothctl -- scan on, I get this sequence with on for 10s, off for 5s - apparently I'm not the first to wonder about this. But when I scan with bluezero, the scan is on for 10s and off for maybe half a second - I see that show_duplicates sets such a filter, so that makes sense with the SE answer. That leaves me with my previous question about additional throttling, or put differently: why do I only get a single advertisement per discovery (per device)? I also see there's btmgmt scan-params <interval> <window> but I can't find docs as to what that does and just changing the value doesn't change the time until discovering on/off appears. Do you happen to know what that's about? If this is a fundamental limitation with using bluez, I wonder whether I should use HCI instead, like suggested in the SE answer. Do you maybe have some thoughts on that?

ukBaz commented 2 months ago

BlueZ is the official Bluetooth stack for Linux and is split between kernel and userspace

There is a good talk on it at: https://youtu.be/VMDyebKT5c4?si=Ek9Gj9Kol5GlGjZE

Which is where the following image comes from:

image

HCI Socket bypasses the bluetoothd that is running on the Linux system that is used by the desktop tools. Using HCI is not a great idea unless you really, really know what you are doing. If you are going to use HCI then stop bluetoothd so there is not a conflict.

All the HCI information is available in the Bluetooth Core Specification which runs to about 3,256 pages for the 5.2 version of the spec.

The BlueZ Bluetooth Mamagement API is the next step up and the lowest level that the BlueZ developers recommend. This does still go via bluetoothd.

The problem for Python users is this bug makes it difficult to access the mgmt socket. There are other duplicate bugs on this in the system. Until they are fixed, this remains off bounds for many Python users.

I did do a proof-of-concept library called btsocket which I believe is used in HomeAssistant but I don't really maintain the btsocket library.

D-Bus API goes via bluetoothd and should be the go to level for most people wanting to interact with the BlueZ API’s. However, it seems the number of people that have done things with D-Bus previously is a relatively small group and it adds another level of indirection to learn.

Bluetooth has features such as device discovery and GATT notifications that are asynchronous. BlueZ uses the GLib mainloop for this and so that needs to be incorporated also depending what you are doing.

Things like scan-params will be described in the Bluetooth Core Specification. I've had a quick look and I can't find the relevant section (but it will be in there somewhere). Unless it is in Bluetooth Core Specification Supplement :-(

The issue you seem to be having is that your system is in an unknown state with the kernel or BlueZ userspace throttling the number of advertisements you are seeing. I am not sure how much more I and the Bluezero library can help. You might be at the stage where you are needing to use an RTOS like Zephyr

The BlueZ D-Bus API did have org.bluez.AdvertisementMonitorManager1 and org.bluez.AdvertisementMonitor1 introduced last year. Bluezero has not done anything with it. There is an example at: https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/test/example-adv-monitor

I don't know if this would help with any of the issues you are seeing.

furgerf commented 2 months ago

Thanks for the video and explanations! That helped putting things together.

Now I think I broadly understand what's going on in my setup:

I've stripped down the resetting to this:

def restart():
    adapter.stop_discovery()
    adapter.start_discovery()
    add_timer_seconds(2, restart)

I omitted the show_duplicates because I don't seem to get them anyway and I'm restarting the scan manually. Does that make sense or do you see an issue with this approach?

ukBaz commented 2 months ago

Seems a sensible workaround.

My only other thought was about the version of the kernel and BlueZ you are using.

For the record, I'm testing this on:

~$ uname -rov
6.8.0-40-generic #40~22.04.3-Ubuntu SMP PREEMPT_DYNAMIC Tue Jul 30 17:30:19 UTC 2 GNU/Linux
~$ btmgmt --version
btmgmt: 5.64
~$ bluetoothctl --version
bluetoothctl: 5.64
furgerf commented 2 months ago

Hmm with this running a bit longer, I again got into the state where it's not discovering the beacon at all anymore, but I think I'll work around it by restarting bluez, which seems to work.

Yes I can see that the bluez version can have something to do with it - I'm only on 5.53, from 2020, unfortunately I can't really update.

Another unresolved issue is the ValueError("Cannot find a device ...") that I mentioned in the original post. This seems to appear with "any" sort of device (with my beacons as well as other devices). Can you guess how this comes about and/or have an idea how to prevent it?

ukBaz commented 2 months ago

Another unresolved issue is the ValueError("Cannot find a device ...") that I mentioned in the original post. This seems to appear with "any" sort of device (with my beacons as well as other devices). Can you guess how this comes about and/or have an idea how to prevent it?

I haven't been able to reproduce this. The error stack that you included originally points to specific code inside Bluezero that handles the InterfacesAdded signal. I don't understand how, if it has got a signal to say the device has been discovered, why it could not find the device on the bluetoothd.

My only thought is around devices using MAC Address Randomization. Bluezero Device takes the MAC address of the adapter and the device and tries to find the D-Bus Object Path for it. For the device, the Bluezero code makes the assumption that the address given will feature in the path (with the : replaced with _. e.g.:

        dev_name = "dev_" + value.lower().replace(":", "_")

Below I have done a re-implementation of the ibeacon scanning without using Bluezero. This just uses the Bluez D-Bus bindings directly. It uses the pydbus library for the D-Bus bindings as this is a more efficient library if you don't want to create peripherals.

It might be worth giving it a try. If nothing else, it might help identify what is a Bluezero issue and what is outside Bluezero's control.

import argparse
from gi.repository import GLib
from pydbus import SystemBus
import uuid

DEVICE_INTERFACE = 'org.bluez.Device1'

def stop_scan():
    """Stop device discovery and quit event loop"""
    adapter.StopDiscovery()
    mainloop.quit()

def clean_beacons(dongle, device_path):
    """
    BlueZ D-Bus API does not show duplicates. This is a
    workaround that removes devices that have been found
    during discovery
    """
    try:
        dongle.RemoveDevice(device_path)
    except GLib.Error as dbus_err:
        if dbus_err.get_dbus_name() == 'org.bluez.Error.DoesNotExist':
            print(f"Error: Device {device_path} not available to remove")

def process_ibeacon(data, beacon_type='iBeacon'):
    """Print iBeacon data in human-readable format"""
    # print('DATA:', data)
    beacon_uuid = uuid.UUID(bytes=bytes(data[2:18]))
    major = int.from_bytes(bytearray(data[18:20]), 'big', signed=False)
    minor = int.from_bytes(bytearray(data[20:22]), 'big', signed=False)
    tx_pwr = int.from_bytes([data[22]], 'big', signed=True)
    print(f'\t\t{beacon_type}: {beacon_uuid} - {major} - {minor} \u2197 {tx_pwr}')

def on_iface_added(owner, path, iface, signal, interfaces_and_properties):
    """
    Event handler for D-Bus interface added.
    Test to see if it is a new Bluetooth device
    """
    iface_path, iface_props = interfaces_and_properties
    if DEVICE_INTERFACE in iface_props:
        on_device_found(iface_path, iface_props[DEVICE_INTERFACE])

def on_device_found(device_path, device_props):
    """
    Handle new Bluetooth device being discovered.
    If it is a beacon of type iBeacon then process it
    """

    manufacturer_data = device_props.get('ManufacturerData')
    if manufacturer_data:
        for mfg_id in manufacturer_data:
            # iBeacon 0x004c
            if mfg_id == 0x004c and manufacturer_data[mfg_id][0] == 0x02:
                process_ibeacon(manufacturer_data[mfg_id])
                clean_beacons(adapter, device_path)

if __name__ == '__main__':
    parser = argparse.ArgumentParser()
    parser.add_argument('-d', '--duration', type=int, default=0,
                        help='Duration of scan [0 for continuous]')
    args = parser.parse_args()
    bus = SystemBus()
    adapter = bus.get('org.bluez', '/org/bluez/hci0')

    bus.subscribe(iface='org.freedesktop.DBus.ObjectManager',
                  signal='InterfacesAdded',
                  signal_fired=on_iface_added)

    mainloop = GLib.MainLoop()

    if args.duration > 0:
        GLib.timeout_add_seconds(args.duration, stop_scan)
    adapter.SetDiscoveryFilter({'DuplicateData': GLib.Variant.new_boolean(False)})
    adapter.StartDiscovery()

    try:
        print('\n\tUse CTRL-C to stop discovery\n')
        mainloop.run()
    except KeyboardInterrupt:
        stop_scan()
furgerf commented 1 month ago

Hi again! I put this aside for a while and am having a fresh look now.

Thanks for the hint regarding MAC randomization. I did some statistics - there are some devices that pop up very often as removed, some quite rarely. Only a few of them seem to be randomized (according to this), so I don't think that's my (main) problem. But it does seem to be related to which other devices are around me.

Thanks also for the pydbus snippet - that seems to behave largely the same as far as I can tell, so there doesn't seem to be an issue specific to bluezero 👍 One thing I noticed though, is that when "show duplicates" is off (like in the snippet, I don't get the ManufacturerData/ServiceData updates (from below).

I did some more digging - maybe you'll humor me some more 😉 I'll describe what I found and have some more questions if you don't mind.


I've been looking at the messages I see in bluetoothctl in particular. When "normal operation" (with device discovered/callback called/device removed) no longer works, I typically see something like that:

[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -65
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -58
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[DEL] Device XX:XX:XX:XX:XX:XX KBPro_507644
[NEW] Device XX:XX:XX:XX:XX:XX KBPro_507644
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -57
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -53
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil
[CHG] Device XX:XX:XX:XX:XX:XX RSSI: -66
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Key: 0x004c
[CHG] Device XX:XX:XX:XX:XX:XX ManufacturerData Value:
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Key: 00002080-0000-1000-8000-00805f9b34fb
[CHG] Device XX:XX:XX:XX:XX:XX ServiceData Value:
[CHG] Device XX:XX:XX:XX:XX:XX RSSI is nil

Basically, I get a bunch of PropertiesChanged messages and occasionally InterfaceRemoved followed by InterfaceAdded.

I modified the Adapter._properties_changed method to try and detect beacons as well, applying the same logic that's in Observer.on_device_found. These DEL/NEW come up when the beacon advertisement payload is found in a PropertiesChanged signal and it's essentially treated like InterfaceAdded. That's nice, but it only works occasionally, not at the expected frequency. Is there a reason not to look for beacon advertisements in PropertiesChanged? Any idea why this would only work sometimes?

My device evidently picks up on additional RSSI updates, but they don't seem to propagate to bluezero (or presumably pydbus, though I didn't try this as well). So another thing I tried was polling Device.RSSI - this gets me values matching the bluetoothctl output (and an exception after the device is removed). That's something that would work for me I think - again: is there a reason not to do something like this? Of course I'd have to do some lifecycle management for when the device enters/exits connectivity range.

Finally, I re-read some of your earlier messages:

While to get the RSSI property change of the device you would need to connect to the signal on the org.bluez.Device1 interface but the path will be /org/bluez/hci0/dev_XX_XX_XX_XX_XX_XX where that path will be constantly changing for privacy.

So it is possible to work on the [CHG] but it is all a bit tricky to manage. This is why I would like to understand what is different about your setup. In bluetoothctl if you do show what does it show. I think the key entries are:

What did you mean by this? Are you referring here to MAC randomization as well? Because, that's not something I'd expect when my beacons aren't configured to do that (nor is it something I observed).

Again, thanks in advance and please let me know if I could also help you in some way (e.g. some tasks for this project) 🙂

ukBaz commented 1 month ago

There seems to be something specific to your setup that I'm unable to reproduce at my end. Without being able to reproduce what you are seeing I am somewhat speculating as to what the issues are.

I've updated the pydbus example to not remove beacons from the device list. This is to enable the ability to watch for the onPropertiesChanged on the ibeacons.

I've also added printing out of the RSSI value:

import argparse
from gi.repository import GLib
from pydbus import SystemBus
import uuid

DEVICE_INTERFACE = 'org.bluez.Device1'
APPLE_MFG_ID = 0x004c
APPLE_BEACON_TYPE = 0x02

class Device:
    def __init__(self, device_path):
        self.device = bus.get('org.bluez', device_path)

    def on_beacon_update(self, iface, changed, invalidated):
        print("[CHG]", end=" ")
        process_ibeacon(self.device.ManufacturerData[APPLE_MFG_ID], self.device.RSSI)

def stop_scan():
    """Stop device discovery and quit event loop"""
    adapter.StopDiscovery()
    mainloop.quit()

def clean_beacons(dongle, device_path):
    """
    BlueZ D-Bus API does not show duplicates. This is a
    workaround that removes devices that have been found
    during discovery
    """
    try:
        dongle.RemoveDevice(device_path)
    except GLib.Error as dbus_err:
        if dbus_err.get_dbus_name() == 'org.bluez.Error.DoesNotExist':
            print(f"Error: Device {device_path} not available to remove")

def process_ibeacon(data, rssi, beacon_type='iBeacon'):
    """Print iBeacon data in human-readable format"""
    # print('DATA:', data)
    beacon_uuid = uuid.UUID(bytes=bytes(data[2:18]))
    major = int.from_bytes(bytearray(data[18:20]), 'big', signed=False)
    minor = int.from_bytes(bytearray(data[20:22]), 'big', signed=False)
    tx_pwr = int.from_bytes([data[22]], 'big', signed=True)
    print(f'\t\t{beacon_type}: {beacon_uuid} - {major} - {minor} \u2197 {tx_pwr} \u2198 {rssi}')

def on_iface_added(owner, path, iface, signal, interfaces_and_properties):
    """
    Event handler for D-Bus interface added.
    Test to see if it is a new Bluetooth device
    """
    iface_path, iface_props = interfaces_and_properties
    if DEVICE_INTERFACE in iface_props:
        on_device_found(iface_path, iface_props[DEVICE_INTERFACE])

def subscribe_to_device(device_path):
    device = Device(device_path)
    device.device.onPropertiesChanged = device.on_beacon_update

def on_device_found(device_path, device_props):
    """
    Handle new Bluetooth device being discovered.
    If it is a beacon of type iBeacon then process it
    """

    manufacturer_data = device_props.get('ManufacturerData')
    rssi = device_props.get('RSSI')
    if manufacturer_data:
        for mfg_id in manufacturer_data:
            # iBeacon 0x004c
            if mfg_id == APPLE_MFG_ID and manufacturer_data[mfg_id][0] == APPLE_BEACON_TYPE:
                # print(device_path)
                print("[NEW]", end=" ")
                process_ibeacon(manufacturer_data[mfg_id], rssi)
                # clean_beacons(adapter, device_path)
                subscribe_to_device(device_path)

if __name__ == '__main__':
    parser = argparse.ArgumentParser()
    parser.add_argument('-d', '--duration', type=int, default=0,
                        help='Duration of scan [0 for continuous]')
    args = parser.parse_args()
    bus = SystemBus()
    adapter = bus.get('org.bluez', '/org/bluez/hci0')

    bus.subscribe(iface='org.freedesktop.DBus.ObjectManager',
                  signal='InterfacesAdded',
                  signal_fired=on_iface_added)

    mainloop = GLib.MainLoop()

    if args.duration > 0:
        GLib.timeout_add_seconds(args.duration, stop_scan)
    adapter.SetDiscoveryFilter({'DuplicateData': GLib.Variant.new_boolean(False)})
    adapter.StartDiscovery()

    try:
        print('\n\tUse CTRL-C to stop discovery\n')
        mainloop.run()
    except KeyboardInterrupt:
        stop_scan()

which gave me the following output:

    Use CTRL-C to stop discovery

[NEW]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -75
[NEW]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -84
[CHG]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -81
[NEW]       iBeacon: 50765cb7-d9ea-4e21-99a4-fa879613a492 - 61708 - 30380 ↗ -50 ↘ -87
[CHG]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -85
[CHG]       iBeacon: 50765cb7-d9ea-4e21-99a4-fa879613a492 - 61708 - 30380 ↗ -50 ↘ -87
[CHG]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -75
[CHG]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -81
[CHG]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -85
[CHG]       iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 ↘ -84

Maybe you can give it a try and see if you get better output using the onPropertiesChanged signal on the devices.

FYI: The reason that I get the [NEW] iBeacon: 2686f39c-bada-4658-854a-a62e7e5e8b8d - 1 - 0 ↗ -55 line twice is that I appear to have two beacons giving the same uuid.

/org/bluez/hci0/dev_xx_xx_xx_xx_xx_82
/org/bluez/hci0/dev_xx_xx_xx_xx_xx_76