backends/winrt: fix max pdu update race

[dlech]

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: https://github.com/hbldh/bleak/issues/1497

[JPHutchins]

Confirmed that this fixed the issue, thanks!

[JPHutchins]

I may have spoken too soon but need to investigate further to understand.

[JPHutchins]

I think that I made need to await asyncio.sleep(1) to benefit from this consistently?

[dlech]

Do you see "max_pdu_size_changed event not received, using default" if you enable debug logging?

[JPHutchins]

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!

[JPHutchins]

Do you see "max_pdu_size_changed event not received, using default" if you enable debug logging?

Yes, I get the log in question. I see that the correct value does arrive!

DEBUG:smpclient.transport.ble:Found device: device=BLEDevice(F2:0D:69:5C:11:6F, A SMP DUT), connecting...
DEBUG:bleak.backends.winrt.client:Connecting to BLE device @ F2:0D:69:5C:11:6F
DEBUG:bleak.backends.winrt.client:getting services (service_cache_mode=None, cache_mode=None)...
DEBUG:bleak.backends.winrt.client:max_pdu_size_changed event not received, using default
DEBUG:bleak.backends.winrt.client:session_status_changed_event_handler: id: BluetoothLE#BluetoothLEe0:d4:64:58:c4:91-f2:0d:69:5c:11:6f, error: <BluetoothError.SUCCESS: 0>, status: <GattSessionStatus.ACTIVE: 1>
DEBUG:smpclient.transport.ble:Connected to device=BLEDevice(F2:0D:69:5C:11:6F, A SMP DUT)
DEBUG:bleak.backends.winrt.client:max_pdu_size_changed_handler: 498
self._smp_characteristic.max_write_without_response_size=20

I suppose that increasing the timeout here might resolve the issue but I understand the concern with it already being 1 second: https://github.com/hbldh/bleak/blob/181467f7d7e09e0a7130962a0f7f8db4510ddc59/bleak/backends/winrt/client.py#L500-L505

It appears that the max_pdu_size_changed_handler does not mutate any state of the client or characteristic.

[dlech]

Can you add timestamps to the debug logs so we can see how long it actually takes before the size changed event comes?

[JPHutchins]

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:

2024-05-11 23:16:56 DEBUG    Connecting to BLE device @ C4:35:E3:1E:09:DB
2024-05-11 23:16:56 DEBUG    getting services (service_cache_mode=None, cache_mode=None)...
2024-05-11 23:16:57 DEBUG    max_pdu_size_changed event not received, using default
2024-05-11 23:16:57 DEBUG    session_status_changed_event_handler: id: BluetoothLE#BluetoothLEe0:d4:64:58:c4:91-c4:35:e3:1e:09:db, error: <BluetoothError.SUCCESS: 0>, status: <GattSessionStatus.ACTIVE: 1>
2024-05-11 23:16:57 DEBUG    Connected to device=BLEDevice(C4:35:E3:1E:09:DB, A SMP DUT)
2024-05-11 23:16:58 DEBUG    max_pdu_size_changed_handler: 498
self._smp_characteristic.max_write_without_response_size=20

Second run with milliseconds, this time it got the value on time:

2024-05-11 23:25:08.352 DEBUG    Connecting to BLE device @ C4:35:E3:1E:09:DB
2024-05-11 23:25:08.444 DEBUG    getting services (service_cache_mode=None, cache_mode=None)...
2024-05-11 23:25:09.173 DEBUG    session_status_changed_event_handler: id: BluetoothLE#BluetoothLEe0:d4:64:58:c4:91-c4:35:e3:1e:09:db, error: <BluetoothError.SUCCESS: 0>, status: <GattSessionStatus.ACTIVE: 1>
2024-05-11 23:25:09.298 DEBUG    max_pdu_size_changed_handler: 498
2024-05-11 23:25:09.482 DEBUG    Connected to device=BLEDevice(C4:35:E3:1E:09:DB, A SMP DUT)
self._smp_characteristic.max_write_without_response_size=495

[dlech]

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?