backends/winrt: fix max pdu update race #1552
Conversation
Users have reported that the max pdu size was wrong on some devices. This was happening because the max_pdu_size_changed event was happeing after the get_services() call returned. This adds an event to wait for the max_pdu_size_changed event to happen and updates the characteristics in the service dictionary after the fact to ensure they have the correct value. The service_explorer example is also updated to show the value to help with future troubleshooting. Fixes: #1497
|
Confirmed that this fixed the issue, thanks! |
|
I may have spoken too soon but need to investigate further to understand. |
|
I think that I made need to await asyncio.sleep(1) to benefit from this consistently? |
|
Do you see "max_pdu_size_changed event not received, using default" if you enable debug logging? |
Thank you, I will look next time I am running! |
Yes, I get the log in question. I see that the correct value does arrive! I suppose that increasing the timeout here might resolve the issue but I understand the concern with it already being 1 second: bleak/bleak/backends/winrt/client.py Lines 500 to 505 in 181467f It appears that the max_pdu_size_changed_handler does not mutate any state of the client or characteristic. |
|
Can you add timestamps to the debug logs so we can see how long it actually takes before the size changed event comes? |
Good idea, here's an example: Second run with milliseconds, this time it got the value on time: |
|
Interesting, it seems like it varies quite a bit. It would be interesting to see some Bluetooth packet captures from it connecting and disconnecting a bunch of times so we can see the general distribution of how long it takes. I'm curious to see if there is a delay in sending the request or a delay in the peripheral sending the reply or both. What kind of device is this anyway? |
|
The BLE device is an NRF52840. The laptop has an Intel bluetooth chip. Do you suggest Wireshark for the captures? My gut feeling is that it's related to Window's model for Bluetooth devices. Any ideas for a workaround? |
|
I have a minimal workaround that produces this log: logger.debug(f"Found SMP characteristic: {smp_characteristic=}")
logger.info(f"{smp_characteristic.max_write_without_response_size=}")
if (
platform.system() == "Windows"
and smp_characteristic.max_write_without_response_size == 20
):
# https://github.com/hbldh/bleak/pull/1552#issuecomment-2105573291
logger.warning(
"The SMP characteristic MTU is 20 bytes, possibly a Windows bug, checking again"
)
await asyncio.sleep(2)
smp_characteristic._max_write_without_response_size = (
self._client._backend._session.max_pdu_size - 3 # type: ignore
)
logger.warning(f"{smp_characteristic.max_write_without_response_size=}")Wait another 2 seconds for the |
Yes, that would let us see exactly what is going on. |
|
Are we expecting this to be an issue in Linux as well? I have received a similar report: intercreate/smpclient#21 Should I really be using the max write without response size or is there a better way to get the MTU reliably across all platforms? |
|
Is this with the same peripheral device? |
|
I believe that the chip is also an NRF52840. Nordic has like 50% market share 🤣. Uncertain of exactly what the peripheral is exactly. https://iotbusinessnews.com/2023/09/29/78978-tsr-market-update-bluetooth-low-energy-market/ |
|
If it happens on Linux too, then I will probably just redo windows to avoid the wait/timeout and update the characteristics dict later. If these peripherals just take a long time to exchange this information, then there is nothing you can do besides wait a long time to get the correct info. Again, Bluetooth packet capture would let us actually see if this is really what is happening. |
|
The MTU is always exchanged correctly between devices. Only reported value seems to be wrong. Bellow API returns correct MTU |
Yes, but the problem I understand here is when this happens, not if it happens. |
|
I can capture data if you tell me what exactly is needed. |
|
See https://bleak.readthedocs.io/en/latest/troubleshooting.html#capture-bluetooth-traffic for how to capture Bluetooth packets. Looking for something that can be opened in Wireshark. |
|
I do a thing which I'm not supposed to do https://bleak.readthedocs.io/en/latest/troubleshooting.html#calling-asyncio-run-more-than-once. I will check that first 😃 |
|
After changing to single asyncio run the same problem occures. wireshark log in attachment. |
|
Thanks for the logs. I can see that the time between the MTU request and response was within 200 ms. 
Was this on Windows? How long did it take to get the PDU size changed event in Bleak during this capture? |
|
It is ubuntu 22. |
|
The value is different depending how you check it. The second on is always correct. The first is correct only sometimes. INFO smp_characteristic.max_write_without_response_size=20
INFO self._max_write_without_response_size=495You can see the code here https://github.com/intercreate/smpclient/blob/8b9111deb9f41a9173e21bc29e456e53263166d9/smpclient/transport/ble.py#L110 |
|
I would suggest starting a new issue abut the same thing happening on BlueZ since this issue was about Windows specifically. If you have to call |
Users have reported that the max pdu size was wrong on some devices. This was happening because the max_pdu_size_changed event was happeing after the get_services() call returned.
This adds an event to wait for the max_pdu_size_changed event to happen and updates the characteristics in the service dictionary after the fact to ensure they have the correct value.
The service_explorer example is also updated to show the value to help with future troubleshooting.
Fixes: #1497