When async-client fails to connect, the client callback `onConnectFail` doesn't get called

[tbekas]

NimBLE-Arduino: 2.3.2
Platform: pioarduino 54.03.20
Framework: Arduino 3.2.0
ESP-IDF: v5.4.1
Board: ESP32-C6
BLE Device: Xbox Wireless Controller (firmware 5.x)

On about ~10-20% connection attempts, my BLE gamepad doesn't seem to connect successfully with the board. It wouldn't be a problem if I my onConnectFail callback would get called, but it doesn't.

This is the log from unsuccessfull connect attempt:

I NimBLEScan: New advertiser: ec:83:50:6e:5c:71
D NimBLEScanCallbacks: Discovered: Name: , Address: ec:83:50:6e:5c:71, appearance: 964, manufacturer data: 060000, serviceUUID: 0x1812, txPower: 20
I NimBLEScan: Scan response from: ec:83:50:6e:5c:71
DEBUG Device discovered, address: ec:83:50:6e:5c:71, address type: 0, name: Xbox Wireless Controller
INFO Attempting to connect to a device, address: ec:83:50:6e:5c:71
D NimBLEClient: >> connect(ec:83:50:6e:5c:71)
D NimBLEScan: >> stop()
D NimBLEScan: << stop()
D NimBLEScan: erase device: ec:83:50:6e:5c:71
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_DISCONNECT
D NimBLEClient: my inserted log: disconnect reason is 0x023e
D NimBLEClient: my inserted log: event->disconnect.conn.conn_handle is 0

no more logs

I was digging into the library code so I've inserted two log lines into the NimBLEClient (inserted just after the line 935). The logged reason is Connection Failed to be Established according to docs. While the conn_handle from event object is 0.

NimBLE-Arduino/src/NimBLEClient.cpp

Lines 934 to 940 in 20097ff

	switch (event->type) {
	case BLE_GAP_EVENT_DISCONNECT: {
	// workaround for bug in NimBLE stack where disconnect event argument is not passed correctly
	pClient = NimBLEDevice::getClientByHandle(event->disconnect.conn.conn_handle);
	if (pClient == nullptr) {
	return 0;
	}

What happens next is that NimBLEDevice::getClientByHandle returns nullptr, so the function NimBLE::handleGapEvent simply returns 0 without notyfing the applicaiton code about an unsuccessful connection attempt.

My application code fragments:

• client connect implementation
• client callbacks onConnectFail implementation

For context - this is how logs look like on a successful connection attempt (80-90% of the time).

I NimBLEScan: New advertiser: ec:83:50:6e:5c:71
D NimBLEScanCallbacks: Discovered: Name: , Address: ec:83:50:6e:5c:71, appearance: 964, manufacturer data: 060000, serviceUUID: 0x1812, txPower: 20
I NimBLEScan: Scan response from: ec:83:50:6e:5c:71
DEBUG Device discovered, address: ec:83:50:6e:5c:71, address type: 0, name: Xbox Wireless Controller
INFO Attempting to connect to a device, address: ec:83:50:6e:5c:71
D NimBLEClient: >> connect(ec:83:50:6e:5c:71)
D NimBLEScan: >> stop()
D NimBLEScan: << stop()
D NimBLEScan: erase device: ec:83:50:6e:5c:71
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_CONNECT
DEBUG Connected to a device, address: ec:83:50:6e:5c:71
D NimBLEClient: >> secureConnection()
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_LINK_ESTAB
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_DATA_LEN_CHG
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_MTU
I NimBLEClient: mtu update: mtu=23
D NimBLEClientCallbacks: onMTUChange: default
D NimBLEClient: << handleGapEvent
D NimBLEClient: exchangeMTUCb: status=0, mtu=23
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_PARING_COMPLETE
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_ENC_CHANGE
INFO Bonded successfully with a device, address: ec:83:50:6e:5c:71

[h2zero]

Ooof, looks like espressf's changes have buggered how this worked and no longer calls ON_CONNECT event with the error code. I'll try to work around this.

[h2zero]

please try the PR and let me know

[tbekas]

First of all thank you for addressing the issue so fast.

I tried the code from the linked PR and the issue seem to persist - the onConnectFail callback wasn't called. The log can be found below.

I NimBLEScan: Scan response from: ec:83:50:6e:5c:71
DEBUG Device discovered, address: ec:83:50:6e:5c:71, address type: 0, name: Xbox Wireless Controller
INFO Attempting to connect to a device, address: ec:83:50:6e:5c:71
D NimBLEClient: >> connect(ec:83:50:6e:5c:71)
D NimBLEScan: >> stop()
D NimBLEScan: << stop()
D NimBLEScan: erase device: ec:83:50:6e:5c:71
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_DISCONNECT
E NimBLEClient: Failed to find connection info; rc=7

no more logs

[tbekas]

I tested the latest changes and they fix the issue, I receive the onConnectFail callback and I can handle the situation. Thank you!

This is the log after the fix, the line starting with ERROR is from my onConnectFail handler.

D NimBLEScanCallbacks: Discovered: Name: , Address: 12:8e:68:f4:b9:bc, manufacturer data: 060001092022c74d2cfd517651032c10a2d43d2a31c8443bd87d9d74a3
D NimBLEScan: erase device: 12:8e:68:f4:b9:bc
I NimBLEScan: Scan response from: ec:83:50:6e:5c:71
INFO Attempting to connect to a device, address: ec:83:50:6e:5c:71
D NimBLEClient: >> connect(ec:83:50:6e:5c:71)
D NimBLEScan: >> stop()
D NimBLEScan: << stop()
D NimBLEScan: erase device: ec:83:50:6e:5c:71
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_DISCONNECT
D NimBLEClient: disconnect; reason=574,
ERROR Failed connecting to a device, address: ec:83:50:6e:5c:71, reason: 0x023e
D NimBLEScan: >> start: duration=30000
D NimBLEScan: Scan started
D NimBLEScan: << start()
D NimBLEClient: << handleGapEvent
I NimBLEScan: New advertiser: 15:47:ae:24:d8:aa
D NimBLEScanCallbacks: Discovered: Name: , Address: 15:47:ae:24:d8:aa, manufacturer data: 06000109202249fcc66426d7519d93e9759be774ba70144649ad2ea93d
D NimBLEScan: erase device: 15:47:ae:24:d8:aa
I NimBLEScan: New advertiser: a0:d0:5b:95:eb:ae
D NimBLEScanCallbacks: Discovered: Name: , Address: a0:d0:5b:95:eb:ae, manufacturer data: 75004204834011220703a0d05b95ebae0001a2d05b95ebad0106
I NimBLEScan: New advertiser: ec:83:50:6e:5c:71
D NimBLEScanCallbacks: Discovered: Name: , Address: ec:83:50:6e:5c:71, appearance: 964, manufacturer data: 060000, serviceUUID: 0x1812, txPower: 20
I NimBLEScan: Scan response from: ec:83:50:6e:5c:71
INFO Attempting to connect to a device, address: ec:83:50:6e:5c:71
D NimBLEClient: >> connect(ec:83:50:6e:5c:71)
D NimBLEScan: >> stop()
D NimBLEScan: << stop()
D NimBLEScan: erase device: ec:83:50:6e:5c:71
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_CONNECT
D NimBLEClient: >> secureConnection()
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_LINK_ESTAB
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_PARING_COMPLETE
D NimBLEClient: >> handleGapEvent BLE_GAP_EVENT_ENC_CHANGE
INFO Bonded successfully with a device, address: ec:83:50:6e:5c:71