Not consistently recognizing ibeacons

[furgerf]

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]

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

python-bluezero/bluezero/adapter.py

Lines 230 to 237 in e120285

	def show_duplicates(self):
	"""
	Show every advertisement from a device during
	Device Discovery if it contains ManufacturerData and/or
	ServiceData irrespective of whether they have been
	discovered previously
	"""
	self.adapter_methods.SetDiscoveryFilter({'DuplicateData': True})

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]

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]

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]

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:

• Device is added in bluetoothctl
• (Nothing in bluezero)
• Device is removed in bluetoothctl
• Immediately, device is added and removed in bluezero -> presumably this weird behavior is why it's removed surprisingly fast in bluezero
• (There may be 1-2 additional "device-removed" in bluezero until the sequence repeats.)

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:

• Bluezero only finds out about a device when it's removed some other way. Does bluezero normally find out about that immediately?
• Bluezero attempts to remove the same device multiple times. (I don't see how it would be added to the remove_list multiple times, without also leading to multiple on_ibeacon callback invocations.)

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]

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]

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]

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]

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]

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

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]

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

python-bluezero/bluezero/async_tools.py

Lines 14 to 27 in e120285

	def add_timer_ms(time, callback, data=None):
	"""Call given callback every x milliseconds"""
	if data:
	GLib.timeout_add(time, callback, data)
	else:
	GLib.timeout_add(time, callback)
	def add_timer_seconds(time, callback, data=None):
	"""Call given callback every x seconds"""
	if data:
	GLib.timeout_add_seconds(time, callback, data)
	else:
	GLib.timeout_add_seconds(time, callback)

?

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]

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]

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:

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]

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

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

• For whatever reason, I'm not getting the "duplicates" but just max 1 advertisement per "scan cycle". Because that scan cycle is 10s on/1s off (with the show-duplicates-filter), I used to have that ~11s interval.
• For whatever reason, when the scanning isn't restarted manually I get these PropertiesChanged signals instead of InterfacesAdded after ~30min.
• Calling e.g. stop_discovery from a thread has no effect (e.g. I don't see hci0 type 7 discovering off in btmgmt after the call), that's why earlier experiments have failed.
• By actually restarting discovery using the async_tools.add_timer_seconds, I avoid the previous issue and can actually "control" the rate of advertisements I receive.

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]

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]

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?