aioble drops notifications

[brianreinhold]

A glucose meter following the BT-SIG profile only stores measurements which must be retrieved by a Record Access Control Point (RACP) transaction. With aioble one is faced with the challenge of invoking the RACP transaction to transfer the data which causes the device to notify its stored data records. When all have been notified an indication is sent on the RACP characteristic.

One can see the challenge here - there are two nested await operations. Clearly impossible without placing one of these in a task.
Thus the RACP action to transfer is placed in a task.
Then one can write the command on the RACP characteristic.
Follow with a while loop that runs until the task completes (indication received)
The while loop has two consecutive await actions, one on the Glucose Measurement characteristic notification followed by the await on the Glucose Context Measurement characteristic notification. Fortunately the response of the Glucose Measurement Notification has a flag indicating if there is a following context measurement.

The issue is that these notifications are sent basically as fast as the device can dump them. So a log looks like this for a case with 3 stored measurements from a Roche Accu-chek Guide:

2024-11-05 00:16:30 DEBUG bt_sig_glucose: LNI: Number of stored measurements b'\x05\x00\x03\x00'
                                                                           // the 05, 00 indicates success and the 03, 00 is the number of msmts (little endian)
2024-11-05 00:16:30 DEBUG bt_sig_glucose: LNI: Task to wait for RACP indication started 
2024-11-05 00:16:30 DEBUG bt_sig_glucose: LNI: Send RACP command to transfer all records
LNI: AIOBLE: Notify received
LNI: AIOBLE: Notify received
LNI: AIOBLE: Notify received
LNI: AIOBLE: Notify received
LNI: AIOBLE: Notify received
LNI: AIOBLE: Notify received
LNI: AIOBLE: Indication received
2024-11-05 00:16:30 DEBUG bt_sig_glucose: LNI: Waiting for msmts
2024-11-05 00:16:30 DEBUG bt_sig_glucose: LNI: RACP indication: b'\x06\x00\x01\x01'.  // Indicates successful RACP transfer all
2024-11-05 00:16:30 DEBUG bt_sig_glucose: LNI: 1b 3b 00 e6 07 08 05 14 08 19 28 1b 2f b0 f8 00 08
2024-11-05 00:16:30 DEBUG bt_sig_glucose: LNI: 02 3b 00 01
2024-11-05 00:16:31 DEBUG bt_sig_glucose: LNI: Waiting for msmts
2024-11-05 00:16:31 DEBUG bt_sig_glucose: LNI: Exiting RACP task.

All the notifications are lost or overwritten by the aioble library except the last two (a single stored measurement contains both a measurement notification and measurement context notification.

Why is aioble losing all these notifications? Is the only way to rescue this problem to write code that intercepts the notification and puts them into an application queue? The aioble queue is clearly overwritten or at least they are not dumped by the *.notified() method as expected: msmt: bytes = await asyncio.wait_for(msmt_char.notified(), 1.0)

I tried the reverse as well - placing the notification handler in a task and invoking the racp commands 'outside'. I also added prints of the received notification bytes at the aioble level. I get the same result:

2024-11-05 11:36:12 DEBUG bt_sig_glucose: LNI: Number of stored measurements b'\x05\x00\x03\x00'
2024-11-05 11:36:12 DEBUG bt_sig_glucose: LNI: Waiting for msmts
2024-11-05 11:36:12 DEBUG bt_sig_glucose: LNI: Send RACP command to transfer all records
LNI: AIOBLE: Notify received 1b 39 00 e4 07 07 1f 0b 2e 09 00 00 8d b0 f8 00 00
LNI: AIOBLE: Notify received 02 39 00 02
LNI: AIOBLE: Notify received 1b 3a 00 e4 07 0b 04 0f 25 02 00 00 93 b1 f8 00 00
LNI: AIOBLE: Notify received 02 3a 00 01
LNI: AIOBLE: Notify received 1b 3b 00 e6 07 08 05 14 08 19 28 1b 2f b0 f8 00 08
LNI: AIOBLE: Notify received 02 3b 00 01
LNI: AIOBLE: Indication received
2024-11-05 11:36:12 DEBUG bt_sig_glucose: LNI: 1b 3a 00 e4 07 0b 04 0f 25 02 00 00 93 b1 f8 00 00
2024-11-05 11:36:12 DEBUG bt_sig_glucose: LNI: RACP indication: b'\x06\x00\x01\x01'.
2024-11-05 11:36:12 DEBUG bt_sig_glucose: LNI: RACP transfer-all task completed. Disconnecting.
LNI: Setting to disconnected
LNI: AIOBLE: Peripheral disconnect. Handle 64
2024-11-05 11:36:12 DEBUG bt_sig_glucose: LNI: 02 3b 00 01

But now it is clearer to see that the first 4 notifications are dropped.

[brianreinhold]

It turns out that aioble limits the notification queue size to 1 which is totally unrealistic for real devices, especially those with stored data that tend to dump as fast as the protocol will allow.

I set it to 10 in the client module

        if properties & _FLAG_NOTIFY:
            # Fired when a notification arrives.
            self._notify_event = asyncio.ThreadSafeFlag()
            # Data for the most recent notification.
            self._notify_queue = deque((), 10)
        if properties & _FLAG_INDICATE:
            # Same for indications.
            self._indicate_event = asyncio.ThreadSafeFlag()
            self._indicate_queue = deque((), 1)

But I am not sure of the side effects. This greatly helped the problem as now I get notified (at application level) of all but the last notification. There is probably a fencepost error somewhere as the code was clearly not designed to handle a queue of more than one. An event is not get created that has to be triggered for the last one.

It's probably not as necessary for indications as a device has to wait for an indication response before sending another one. Such is not the case for notifications - they can be dumped one after the other.

[ekspla]

This issue seems to be related to the issue I also encountered. Discussion, explanation of workaround.

For the side effect in my case, I sometimes saw an error caused by pointing an empty queue when notify_event was not explicitly cleared.