Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 48.24%. Comparing base (8a40874) to head (00fbafe).
⚠️ Report is 1 commits behind head on develop.

@@             Coverage Diff             @@
##           develop    #1888      +/-   ##
===========================================
+ Coverage    46.26%   48.24%   +1.97%     
===========================================
  Files           38       38              
  Lines         3839     3839              
  Branches       463      463              
===========================================
+ Hits          1776     1852      +76     
+ Misses        1953     1864      -89     
- Partials       110      123      +13     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

do you have any idea what could be causing this?

According to the BlueZ source code, it should only be 2 seconds.

#define DISCONNECT_TIMER	2

...

void device_request_disconnect(struct btd_device *device, DBusMessage *msg)
{
	...
	device->disconn_timer = timeout_add_seconds(DISCONNECT_TIMER,
							disconnect_all,
							device, NULL);
	...
}

There are 3 possible implementations for timeout_add_seconds() though depending on which run loop is being used (ell, glib or mainloop). So maybe whichever implementation is being used on alpine isn't working well? Or maybe the timer source in qemu isn't working well? I would expect a timer on the order of 2 seconds to be fairly accurate though. Certainly not 10x off.

do you have any idea what could be causing this?

I just tried running tests locally with --bleak-bluez-vhci for the first time and it was super-slow too. So I think most of the problem is with the vhci interface. I wonder if the problem is a performance issue with pyserial-asyncio? I will test it.

Profiling shows that it is spending all of it's time on epoll() in the asyncio run loop. I haven't been able to figure out how to show which tasks/coroutines are waiting at this time though.

The problem seems to be in the Linux kernel. Running btmon shows:

> ACL Data RX: Handle 0 flags 0x02 dlen 5                                       #178 [hci0] 8.012991
      ATT: Write Response (0x13) len 0
bluetoothd[3701]: @ MGMT Command: Disconnect (0x0014) plen 7                {0x0001} [hci0] 9.918092
        LE Address: DA:96:79:7A:C8:B2 (Static)
< HCI Command: LE Create Connection Cancel (0x08|0x000e) plen 0                 #179 [hci0] 28.448065

We can see the expected 2 second delay from bluetoothd between the last operation (Write Response) and and the MGMT Disconnect command.

However, there is an 18 second delay between the MGMT command to the kernel and actually sending the HCI command.

OK, the disconnect is actually coming from a 20 second timeout in hci_le_create_conn_sync() in the Linux kernel.

I think the kernel is expecting HCI_EV_LE_ENHANCED_CONN_COMPLETE instead of HCI_EV_LE_CONN_COMPLETE because either HCI_LE_LL_PRIVACY or HCI_LE_EXT_ADV is supported on the VHCI device. So we should be able to tweak bumble to give the expected response.

diff --git a/tests/integration/bluez_controller.py b/tests/integration/bluez_controller.py
index f8f5142..07168c4 100644
--- a/tests/integration/bluez_controller.py
+++ b/tests/integration/bluez_controller.py
@@ -147,6 +147,7 @@ async def open_bluez_bluetooth_controller_link(
                 host_sink=hci_transport.sink,
                 link=link,
             )
+            bluez_controller.le_features = bytes.fromhex("0000000000000000")
             bluez_controller.manufacturer_name = BLEAK_TEST_MANUFACTURER_ID
 
             # Wait up to 5 seconds for the new adapter to appear via InterfacesAdded

Seems to do the trick. I just set it to all 0s and didn't check to see what else I was disabling yet though.

Thanks for your investigations in the timing problem and fixing it in #1890. I would never have found it so quickly.

I have addressed all your points, so this PR is ready for a new review.

I have addressed all your points, so this PR is ready for a new review.

Thanks!