Logitech M240 mouse connection failure after successful pairing

[retsyx]

I have a Logitech M240 mouse that I want to pair and connect to over time on Windows with a WinUSB driven BLE dongle. The quick summary is that initial pairing and HID reports always work. However, subsequent reconnections (by restarting the program, or after replacing batteries in the mouse, for example) always fail, and the only way to establish a connection again is to initiate a pairing.

I'm using the keyboard.py example to communicate with the mouse. I've tried pairing the mouse with the keyboard.py example code directly (it calls pair()) and with apps/pair.py. In both cases pairing succeeds. When using keyboard.py, the mouse generates HID reports that are logged in keyboard.py so it definitely works after initial pairing. Subsequent connection attempts always fail.

What is wrong?

The configuration file, central.json, I'm using is this:

{
    "name": "Bumble",
    "address": "78:20:51:F6:44:C9",
    "keystore": "JsonKeyStore"
}

I verified the local address of the host using apps/console.py (I've tried with and without the /P suffix).
I've also verified that the JsonKeyStore key file is indeed created and populated with credentials.

(mau) PS C:\Users\retsyx\AppData\Local\Google\Bumble\Pairing> cat 78-20-51-f6-44-c9-p.json
{
    "78:20:51:F6:44:C9/P": {
        "D0:45:A0:E9:B9:33": {
            "address_type": 1,
            "irk": {
                "authenticated": false,
                "value": "919eb15c3d699e48404add2c72eefd94"
            },
            "ltk": {
                "authenticated": false,
                "value": "0677c9aad8089802185aee115fb3d33c"
            }
        }
    }
}

Here is a log of the initial pairing with apps/pair.py

(mau) PS C:\> python .\Lib\site-packages\bumble\apps\pair.py .\central.json usb:1 D0:45:A0:E9:B9:33

<<< connecting to HCI...
<<< connected
=== Connecting to D0:45:A0:E9:B9:33...
<<< Connection: Connection(transport=LE, handle=0x0010, role=CENTRAL, self_address=78:20:51:F6:44:C9, self_resolvable_address=None, peer_address=D0:45:A0:E9:B9:33, peer_resolvable_address=None)
***-----------------------------------
*** Pairing starting
***-----------------------------------
@@@-----------------------------------
@@@ Connection is encrypted
@@@-----------------------------------
***-----------------------------------
*** Paired! (peer identity=D0:45:A0:E9:B9:33)
*** address_type: 1
*** ltk:
***   value: 0677c9aad8089802185aee115fb3d33c
***   authenticated: False
*** irk:
***   value: 919eb15c3d699e48404add2c72eefd94
***   authenticated: False
***-----------------------------------

Output of keyboard.py, demonstrating subsequent connection failure:

(mau) PS C:\> python keyboard.py .\central.json usb:1 connect D0:45:A0:E9:B9:33
17:49:40.463 D asyncio: Using proactor: IocpProactor
17:49:40.544 D bumble.transport.usb: USB Device: Bus 001 Device 002: ID 2357:0604
17:49:40.545 D bumble.transport.usb: selected endpoints: configuration=1, interface=0, setting=0, acl_in=0x82, acl_out=0x02, events_in=0x81, 
17:49:40.545 D bumble.transport.usb: current configuration = 1
17:49:40.546 D bumble.transport.usb: starting USB event loop
17:49:40.546 D bumble.drivers: Probing driver class: rtk
17:49:40.546 D bumble.host: ### HOST -> CONTROLLER: HCI_RESET_COMMAND
17:49:40.558 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 3
  command_opcode:          HCI_RESET_COMMAND
  return_parameters:       HCI_SUCCESS
17:49:40.558 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_LOCAL_VERSION_INFORMATION_COMMAND
17:49:40.561 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_LOCAL_VERSION_INFORMATION_COMMAND
  return_parameters:
    status:             HCI_SUCCESS
    hci_version:        10
    hci_subversion:     57286
    lmp_version:        10
    company_identifier: 93
    lmp_subversion:     55586
17:49:40.561 D bumble.drivers.rtk: looking for a driver: 0xD922 (0x0A, 0xDFC6)
17:49:40.561 D bumble.drivers.rtk: firmware already loaded or no known driver for this device
17:49:40.561 D bumble.drivers: Probing driver class: intel
17:49:40.561 D bumble.drivers.intel: USB device (2357, 0604) not in known list
17:49:40.561 D bumble.host: ### HOST -> CONTROLLER: HCI_RESET_COMMAND
17:49:40.574 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 3
  command_opcode:          HCI_RESET_COMMAND
  return_parameters:       HCI_SUCCESS
17:49:40.574 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_LOCAL_SUPPORTED_COMMANDS_COMMAND
17:49:40.582 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_LOCAL_SUPPORTED_COMMANDS_COMMAND
  return_parameters:
    status:             HCI_SUCCESS
    supported_commands: ffffff03ccffffff3ffffc9ff30fe8fe3fe78fff1c00000061f7ffff7f00e0fff7c007f8ffe38003000000000000000000000000000000000000000000000000
17:49:40.582 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_READ_LOCAL_SUPPORTED_FEATURES_COMMAND
17:49:40.584 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_READ_LOCAL_SUPPORTED_FEATURES_COMMAND
  return_parameters:
    status:      HCI_SUCCESS
    le_features: bd5f660000000000
17:49:40.584 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_LOCAL_VERSION_INFORMATION_COMMAND
17:49:40.587 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_LOCAL_VERSION_INFORMATION_COMMAND
  return_parameters:
    status:             HCI_SUCCESS
    hci_version:        10
    hci_subversion:     57286
    lmp_version:        10
    company_identifier: 93
    lmp_subversion:     55586
17:49:40.588 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_LOCAL_EXTENDED_FEATURES_COMMAND:
  page_number: 0
17:49:40.591 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_LOCAL_EXTENDED_FEATURES_COMMAND
  return_parameters:
    status:                HCI_SUCCESS
    page_number:           0
    maximum_page_number:   2
    extended_lmp_features: fffffffedbfd7b87
17:49:40.591 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_LOCAL_EXTENDED_FEATURES_COMMAND:
  page_number: 1
17:49:40.595 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_LOCAL_EXTENDED_FEATURES_COMMAND
  return_parameters:
    status:                HCI_SUCCESS
    page_number:           1
    maximum_page_number:   2
    extended_lmp_features: 0000000000000000
17:49:40.595 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_LOCAL_EXTENDED_FEATURES_COMMAND:
  page_number: 2
17:49:40.599 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_LOCAL_EXTENDED_FEATURES_COMMAND
  return_parameters:
    status:                HCI_SUCCESS
    page_number:           2
    maximum_page_number:   2
    extended_lmp_features: 5f02000000000000
17:49:40.599 D bumble.host: ### HOST -> CONTROLLER: HCI_SET_EVENT_MASK_COMMAND:
  event_mask: ff9ffbbf07f8bf3d
17:49:40.602 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_SET_EVENT_MASK_COMMAND
  return_parameters:       HCI_SUCCESS
17:49:40.602 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_SET_EVENT_MASK_COMMAND:
  le_event_mask: fffff7ff07e90300
17:49:40.605 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_SET_EVENT_MASK_COMMAND
  return_parameters:       HCI_SUCCESS
17:49:40.605 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_BUFFER_SIZE_COMMAND
17:49:40.608 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_BUFFER_SIZE_COMMAND
  return_parameters:
    status:                                HCI_SUCCESS
    hc_acl_data_packet_length:             1021
    hc_synchronous_data_packet_length:     255
    hc_total_num_acl_data_packets:         6
    hc_total_num_synchronous_data_packets: 12
17:49:40.608 D bumble.host: HCI ACL flow control: hc_acl_data_packet_length=1021,hc_total_num_acl_data_packets=6
17:49:40.608 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_READ_BUFFER_SIZE_COMMAND
17:49:40.611 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_READ_BUFFER_SIZE_COMMAND
  return_parameters:
    status:                        HCI_SUCCESS
    le_acl_data_packet_length:     27
    total_num_le_acl_data_packets: 8
17:49:40.611 D bumble.host: HCI LE ACL flow control: le_acl_data_packet_length=27,total_num_le_acl_data_packets=8
17:49:40.611 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_READ_SUGGESTED_DEFAULT_DATA_LENGTH_COMMAND
17:49:40.614 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_READ_SUGGESTED_DEFAULT_DATA_LENGTH_COMMAND
  return_parameters:
    status:                  HCI_SUCCESS
    suggested_max_tx_octets: 251
    suggested_max_tx_time:   17040
17:49:40.614 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_WRITE_SUGGESTED_DEFAULT_DATA_LENGTH_COMMAND:
  suggested_max_tx_octets: 251
  suggested_max_tx_time:   2120
17:49:40.617 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_WRITE_SUGGESTED_DEFAULT_DATA_LENGTH_COMMAND
  return_parameters:       HCI_SUCCESS
17:49:40.617 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_READ_NUMBER_OF_SUPPORTED_ADVERTISING_SETS_COMMAND
17:49:40.620 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_READ_NUMBER_OF_SUPPORTED_ADVERTISING_SETS_COMMAND
  return_parameters:
    status:                         HCI_SUCCESS
    num_supported_advertising_sets: 4
17:49:40.620 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_READ_MAXIMUM_ADVERTISING_DATA_LENGTH_COMMAND
17:49:40.623 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_READ_MAXIMUM_ADVERTISING_DATA_LENGTH_COMMAND
  return_parameters:
    status:                      HCI_SUCCESS
    max_advertising_data_length: 1024
17:49:40.623 D bumble.host: ### HOST -> CONTROLLER: HCI_READ_BD_ADDR_COMMAND
17:49:40.626 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_READ_BD_ADDR_COMMAND
  return_parameters:
    status:  HCI_SUCCESS
    bd_addr: 78:20:51:F6:44:C9/P
17:49:40.626 D bumble.device: BD_ADDR: 78:20:51:F6:44:C9/P
17:49:40.630 D bumble.keys: JSON keystore: C:\Users\retsyx\AppData\Local\Google\Bumble\Pairing\78-20-51-f6-44-c9-p.json
17:49:40.630 D bumble.host: ### HOST -> CONTROLLER: HCI_WRITE_LE_HOST_SUPPORT_COMMAND:
  le_supported_host:    1
  simultaneous_le_host: 0
17:49:40.633 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_WRITE_LE_HOST_SUPPORT_COMMAND
  return_parameters:       HCI_SUCCESS
17:49:40.633 D bumble.device: LE Random Address: 78:20:51:F6:44:C9
17:49:40.633 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_SET_RANDOM_ADDRESS_COMMAND:
  random_address: 78:20:51:F6:44:C9
17:49:40.636 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_COMPLETE_EVENT:
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_SET_RANDOM_ADDRESS_COMMAND
  return_parameters:       HCI_SUCCESS
17:49:40.636 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_EXTENDED_CREATE_CONNECTION_COMMAND:
  initiator_filter_policy: 0
  own_address_type:        RANDOM
  peer_address_type:       RANDOM_DEVICE
  peer_address:            D0:45:A0:E9:B9:33
  initiating_phys:         LE_1M_PHY
  LE_1M_PHY.scan_interval:           96
  LE_1M_PHY.scan_window:             96
  LE_1M_PHY.connection_interval_min: 12
  LE_1M_PHY.connection_interval_max: 24
  LE_1M_PHY.max_latency:             0
  LE_1M_PHY.supervision_timeout:     72
  LE_1M_PHY.min_ce_length:           0
  LE_1M_PHY.max_ce_length:           0
17:49:40.640 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_STATUS_EVENT:
  status:                  PENDING
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_EXTENDED_CREATE_CONNECTION_COMMAND
17:49:43.366 D bumble.host: ### CONTROLLER -> HOST: HCI_LE_ENHANCED_CONNECTION_COMPLETE_EVENT:
  status:                           HCI_SUCCESS
  connection_handle:                16
  role:                             CENTRAL
  peer_address_type:                RANDOM_DEVICE
  peer_address:                     D0:45:A0:E9:B9:33
  local_resolvable_private_address: 00:00:00:00:00:00
  peer_resolvable_private_address:  00:00:00:00:00:00
  connection_interval:              24
  peripheral_latency:               0
  supervision_timeout:              72
  central_clock_accuracy:           0
17:49:43.367 D bumble.host: ### LE CONNECTION: [0x0010] D0:45:A0:E9:B9:33 as CENTRAL
17:49:43.367 D bumble.device: *** Connection: [0x0010] D0:45:A0:E9:B9:33 CENTRAL
17:49:43.367 D bumble.smp: pairing with self_address=78:20:51:F6:44:C9, peer_address=D0:45:A0:E9:B9:33
17:49:43.370 D bumble.smp: >>> Sending SMP Command on connection [0x0010] D0:45:A0:E9:B9:33: SMP_PAIRING_REQUEST_COMMAND:
  io_capability:               SMP_NO_INPUT_NO_OUTPUT_IO_CAPABILITY
  oob_data_flag:               0
  auth_req:                    bonding_flags=1, MITM=1, sc=1, keypress=0, ct2=0
  maximum_encryption_key_size: 16
  initiator_key_distribution:  ENC,ID
  responder_key_distribution:  ENC,ID
17:49:43.370 D bumble.host: >>> ACL packet enqueue: (CID=6) ACL: handle=0x0010, pb=0, bc=0, data_total_length=11, data=070006000103000d100303
17:49:43.370 D bumble.host: ### HOST -> CONTROLLER: ACL: handle=0x0010, pb=0, bc=0, data_total_length=11, data=070006000103000d100303
17:49:43.530 D bumble.host: ### CONTROLLER -> HOST: HCI_DISCONNECTION_COMPLETE_EVENT:
  status:            HCI_SUCCESS
  connection_handle: 16
  reason:            HCI_CONNECTION_FAILED_TO_BE_ESTABLISHED_ERROR
17:49:43.530 D bumble.host: ### DISCONNECTION: Connection(transport=1, peer_address=D0:45:A0:E9:B9:33), reason=62
17:49:43.530 D bumble.device: *** Disconnection: [0x0010] D0:45:A0:E9:B9:33 as CENTRAL, reason=62
17:49:43.530 D bumble.smp: session end for connection 0x0010
17:49:43.530 D bumble.l2cap: disconnection from 16, cleaning up channels
17:49:43.531 D bumble.transport.usb: waiting for IN[4] transfer cancellation to be done...
17:49:43.531 D bumble.transport.usb: IN[4] transfer cancellation done
17:49:43.531 D bumble.transport.usb: waiting for IN[2] transfer cancellation to be done...
17:49:43.532 D bumble.transport.usb: USB event loop done
17:49:43.532 D bumble.transport.usb: IN[2] transfer cancellation done
Traceback (most recent call last):
  File "C:\Users\retsyx\Documents\mau\keyboard.py", line 274, in <module>
    asyncio.run(main())
  File "C:\Program Files\Python312\Lib\asyncio\runners.py", line 194, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "C:\Program Files\Python312\Lib\asyncio\runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Program Files\Python312\Lib\asyncio\base_events.py", line 687, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "C:\Users\retsyx\Documents\mau\keyboard.py", line 266, in main
    await keyboard_host(device, sys.argv[4])
  File "C:\Users\retsyx\Documents\mau\keyboard.py", line 162, in keyboard_host
    await connection.pair()
  File "C:\Users\retsyx\Documents\mau\Lib\site-packages\bumble\device.py", line 1898, in pair
    return await self.device.pair(self)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\retsyx\Documents\mau\Lib\site-packages\bumble\device.py", line 4394, in pair
    return await self.smp_manager.pair(connection)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\retsyx\Documents\mau\Lib\site-packages\bumble\smp.py", line 2005, in pair
    return await session.pair()
           ^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\retsyx\Documents\mau\Lib\site-packages\bumble\smp.py", line 1296, in pair
    await self.connection.cancel_on_disconnection(self.pairing_result)
asyncio.exceptions.CancelledError: abort: disconnection event occurred.

I can also provide logs of initial pairing success and HID reports with keyboard.py, if that is helpful.

[barbibulle]

I think the issue here is that the keyboard.py example is a bit too simple-minded, as it tries to pair every time it connects, instead of simply authenticating and encrypting the connection in subsequent connections after the initial pairing.
I'll fix that in the example and submit a PR. In the meantime, what you can try is to modify the example, replacing the call await connection.pair() with await connection.encrypt() when connecting to a previously-paired device.

[retsyx]

Thank you for the suggestion. I tried it, but it fails in the same way.

My impression is that the connection fails before any operation can be performed. I think device.connect() is failing for some reason.

To illustrate what I'm seeing, I replaced await connection.pair() with this. Note that the connection fails with or without the sleep():

    connection = await device.connect(peer_address)
    #await connection.pair()
    print('Sleeping 5 seconds')
    await asyncio.sleep(5)
    print('Sleep complete')
    await connection.encrypt()

The connection fails before the 5 second sleep completes. The log excerpt:

...
20:29:52.979 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_EXTENDED_CREATE_CONNECTION_COMMAND:
  initiator_filter_policy: 0
  own_address_type:        RANDOM
  peer_address_type:       RANDOM_DEVICE
  peer_address:            D0:45:A0:E9:B9:33
  initiating_phys:         LE_1M_PHY
  LE_1M_PHY.scan_interval:           96
  LE_1M_PHY.scan_window:             96
  LE_1M_PHY.connection_interval_min: 12
  LE_1M_PHY.connection_interval_max: 24
  LE_1M_PHY.max_latency:             0
  LE_1M_PHY.supervision_timeout:     72
  LE_1M_PHY.min_ce_length:           0
  LE_1M_PHY.max_ce_length:           0
20:29:52.982 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_STATUS_EVENT:
  status:                  PENDING
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_EXTENDED_CREATE_CONNECTION_COMMAND
20:30:01.405 D bumble.host: ### CONTROLLER -> HOST: HCI_LE_ENHANCED_CONNECTION_COMPLETE_EVENT:
  status:                           HCI_SUCCESS
  connection_handle:                16
  role:                             CENTRAL
  peer_address_type:                RANDOM_DEVICE
  peer_address:                     D0:45:A0:E9:B9:33
  local_resolvable_private_address: 00:00:00:00:00:00
  peer_resolvable_private_address:  00:00:00:00:00:00
  connection_interval:              24
  peripheral_latency:               0
  supervision_timeout:              72
  central_clock_accuracy:           0
20:30:01.405 D bumble.host: ### LE CONNECTION: [0x0010] D0:45:A0:E9:B9:33 as CENTRAL
20:30:01.406 D bumble.device: *** Connection: [0x0010] D0:45:A0:E9:B9:33 CENTRAL
Sleeping 5 seconds
20:30:01.570 D bumble.host: ### CONTROLLER -> HOST: HCI_DISCONNECTION_COMPLETE_EVENT:
  status:            HCI_SUCCESS
  connection_handle: 16
  reason:            HCI_CONNECTION_FAILED_TO_BE_ESTABLISHED_ERROR
20:30:01.570 D bumble.host: ### DISCONNECTION: Connection(transport=1, peer_address=D0:45:A0:E9:B9:33), reason=62
20:30:01.570 D bumble.device: *** Disconnection: [0x0010] D0:45:A0:E9:B9:33 as CENTRAL, reason=62
20:30:01.571 D bumble.l2cap: disconnection from 16, cleaning up channels
Sleep complete
20:30:06.423 D bumble.device: Looking up key for D0:45:A0:E9:B9:33
20:30:06.424 D bumble.host: ### HOST -> CONTROLLER: HCI_LE_ENABLE_ENCRYPTION_COMMAND:
  connection_handle:     16
  random_number:         0000000000000000
  encrypted_diversifier: 0
  long_term_key:         0677c9aad8089802185aee115fb3d33c
20:30:06.426 D bumble.host: ### CONTROLLER -> HOST: HCI_COMMAND_STATUS_EVENT:
  status:                  HCI_UNKNOWN_CONNECTION_IDENTIFIER_ERROR
  num_hci_command_packets: 2
  command_opcode:          HCI_LE_ENABLE_ENCRYPTION_COMMAND
20:30:06.426 W bumble.host: HCI_LE_ENABLE_ENCRYPTION_COMMAND failed (HCI_UNKNOWN_CONNECTION_IDENTIFIER_ERROR)
20:30:06.427 E bumble.host: !!! Exception while sending command:
...

[barbibulle]

That's quite puzzling. What we see here is that the connection actually succeeds (timestamp 20:30:01.405), but then a disconnection happens almost immediately after (timestamp 20:30:01.570, so 165 milliseconds later). The disconnection reason (HCI_CONNECTION_FAILED_TO_BE_ESTABLISHED_ERROR, value 0x3E) has a name that's a bit misleading . The full description of this error is:

Connection Failed to be Established / Synchronization Timeout
The Connection Failed to be Established / Synchronization Timeout error code indicates
that the LL initiated a connection or initiated synchronization but the connection has
failed to be established or the Link Layer failed to synchronize within the specified time.

It's not clear what would be causing this, especially given that you observe that the connection is actually when first pairing.
Are you able to try with a different Bluetooth controller, to see if this is a radio-level issue or something higher up the stack?

[retsyx]

I initially encountered this issue with the PC's onboard Intel Bluetooth adapter (driven by WinUSB). I had already encountered unrelated general flakiness with that adapter in the past when using the default drivers and the Windows Bluetooth stack - every so often it would require reinstalling the Intel drivers to get the system Bluetooth working again. To rule out the Intel adapter, I am now using a brand new TP-LINK UB500 dongle which from looking at the Bumble logs is a RTK device (I downloaded all the RTK firmware images and Bumble seems to be happy with it).

Is there anything else I should try?

FWIW, the mouse has worked fine with the Windows Bluetooth stack (on the Intel adapter). And with a Mac.

[barbibulle]

Not sure what else to try, short of getting a radio-level sniffer trace. I'll try to find a similar device and run some tests on my side to see if I can replicate this problem.

[retsyx]

The Logitech M240 increments its address every time it is paired again.

I have attached nrf52840 sniffer captures of a successful pairing and of a failed connection attempt. The mouse MAC addresses for each capture are different because I performed multiple pairings in between. I'm not entirely sure if the sniffer is capturing everything.

The capture files are in Archive.zip

pairing2.pcapng shows a successful pairing along with what I suspect are HID report packets (I haven't tried decrypting the traffic). The mouse MAC is d0:45:a0:e9:b9:44.

Key info for this pairing is:

        "D0:45:A0:E9:B9:44": {
            "address_type": 1,
            "irk": {
                "authenticated": false,
                "value": "7dbce3a46c4d3a4661948b61a1c98107"
            },
            "ltk": {
                "authenticated": false,
                "value": "63611ff05e500deeac3c66a052dcd0da"
            }
        }

connect2.pcapng shows a connection failure. The mouse MAC is d0:45:a0:e9:b9:36. To me it looks like there is simply no response from the mouse (assuming the sniffer is indeed sniffing everything). Note that in this capture the unanswered packets are encryption request packets. This is because connection.encrypt() was called in the code. If the code sleeps for 5 seconds instead, then empty PDU packets go unanswered.

Maybe the mouse is waiting for a very specific initial packet?!

Key info for this pairing is:

        "D0:45:A0:E9:B9:36": {
            "address_type": 1,
            "irk": {
                "authenticated": false,
                "value": "a521e55cd04c625cf8499adca606221a"
            },
            "ltk": {
                "authenticated": false,
                "value": "f7a48d4806aa3caa42ec9297afc773bb"
            }
        }

[retsyx]

I believe I have figured out the problem, and I now have it working. Although, my knowledge of BLE internals is rather limited so the fix doesn't make sense to me, and I would very much appreciate an explanation, if you can provide one.

Now that I have a sniffer, I compared pairing and re-connection captures between Bumble and a Mac. The first difference between the two that I noticed, in the re-connection CONNECT_IND packet from the central device was the Mac advertising the TX address as public while Bumble advertised it as random. So I changed the device.connect() line in keyboard.py to:

connection = await device.connect(peer_address, own_address_type = bumble.hci.OwnAddressType.PUBLIC)

And now everything works. I haven't sniffed it to compare.

Thank you for your help!

[barbibulle]

It's great that you found a way to make it work. I'm still somewhat surprised by the solution though. What appears to happen here is that even though the Logitech mouse uses rotating private addresses (as it should, that's standard for BLE with privacy support), you are attempting to connect to the mouse's public address (D0:45:A0:E9:B9:36), and that seems to succeed (even if you get disconnected right after). Unless the mouse is in pairing mode, it shouldn't be advertising and accepting connections with its public address, it should only be advertising with a (rotating) Resolvable Private Address (RPA). The client (Bumble app in your case) is supposed to use the resolving key (IRK), which it obtained during pairing, to resolve the RPA into the mouse's Public Address, and connect to that address. (Bumble's connect() method has a always_resolve argument, which is False by default, which tells the method whether the connecting should be done directly to the address, or try to resolve the address first. I need to improve this, to default always_resolve to True when connecting to a previously paired and saved address (i.e "bonded")).
What's likely going on is the the mouse is accepting connections on its public address, but only from devices that connect with a Random Private Address, or from previously-paired devices that connect with their public address (hence the own_address_type = bumble.hci.OwnAddressType.PUBLIC here). That's a strange behavior, because the mouse should not be advertising with its public address (that defeats the LE privacy and the use of rotating Resolvable Private Addresses), and the computer should also not be connecting with its public address (because that reveals the public address, which leaks information).

It would be interesting to try this alternative connection mode: after pairing, try connecting with device.connect(peer_address, always_resolve=True), leaving out own_address_type as default).

[retsyx]

always_resolve=True fails with the same connection failure error reported in Bumble (I didn't re-pair, or trace it).

I have an observation from Linux that may or may not be helpful (I don't know enough about BLE). I've paired Linux with other BLE peripherals that use random addresses (Siri remotes). What I observed in those cases is that after linux pairs with the peripheral at its random address, Linux resolves the peripheral's public address and uses it for internal bookkeeping (for example, to reconnect to the peripheral, you need to use the public address).

While debugging this issue, I tried pairing this mouse with Linux to see how it behaved. After pairing, Linux had the peripheral referenced using the address that was used at pairing - so the not so random address.