Connection failed

[bpfingsten-crestron]

Description

After scanning and locating my ESP32 device I call the connect method, but this fails to connect and when I register a ESPBLEDelegate the periperalFailedToConnect is called with an error description of "Connection timeout. Unable to read BLE characteristic on time." I am able to use just CoreBluetooth code and discover my expected service (UUID: FFFF) and the characteristics of that service (UUID: FF01 and FF02). The device I am using has an LED that turns blue when it has a BLE connection which does happen for a few seconds before turning back to white indicating a waiting/pending status. The logs show that is discovering the service and characteristics...

10:08:36.637 | ESPBleTransport.peripheral(:didDiscoverServices:) (304) : Peripheral did discover services.
10:08:36.758 | ESPBleTransport.peripheral(:didDiscoverCharacteristicsFor:error:) (315) : Peripheral did discover chatacteristics.
10:08:36.762 | ESPBleTransport.peripheral(:didDiscoverDescriptorsFor:error:) (358) : Did sicover descriptor for characterisitic: <CBCharacteristic: 0x282bd02a0, UUID = FF01, properties = 0x8, value = (null), notifying = NO>
10:08:36.877 | ESPBleTransport.peripheral(:didDiscoverDescriptorsFor:error:) (358) : Did sicover descriptor for characterisitic: <CBCharacteristic: 0x282bd0120, UUID = FF02, properties = 0x12, value = (null), notifying = NO>
10:08:36.936 | ESPBleTransport.peripheral(_:didUpdateValueFor:error:) (365) : Did update value for descriptor: <CBDescriptor: 0x2801b05a0, UUID = Client Characteristic Configuration, value = (null)>
10:08:55.793 | ESPBleTransport.bleConnectionTimeout() (176) : Peripheral connection timeout occured.

I don't know how to proceed at this point.

To Reproduce
Steps to reproduce the behavior:

1. Go to '...'
2. Click on '....'
   ...

Frequency
100%

Expected behavior
Should connect to the device

Screenshots

ESP Device Information:

• ESP-IDF version: not sure
• Example referenced: not sure
• Board type: ESP32-WROVER-E (from ESP32 chip)

iOS information:

• Device type: iPhone
• Device model: iPhone 14
• iOS version: iOS 16.6
• App Version: 1.0

Provisioning information:

• ESPProvision iOS SDK version: 2.1.2
• Device type: BLE
• Security: Unsecure but tried both

ESP Device logs:
From the app:
10:08:26.439 | ESPProvisionManager.searchESPDevices(devicePrefix:transport:security:completionHandler:) (99) : Search ESPDevices called.
10:08:26.440 | ESPBleTransport.init(scanTimeout:deviceNamePrefix:proofOfPossession:username:) (100) : Initalising BLE transport class with scan timeout 5.0
10:08:26.443 | ESPBleTransport.scan(delegate:) (196) : Ble scan started...
10:08:26.460 | ESPBleTransport.centralManagerDidUpdateState(:) (258) : Bluetooth state on
10:08:26.508 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataLocalName": FF2_5C0E2799, "kCBAdvDataTimestamp": 721850906.505408, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataIsConnectable": 1, "kCBAdvDataRxPrimaryPHY": 129]
10:08:26.510 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:FF2_5C0E2799, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:26.511 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataTimestamp": 721850906.507284, "kCBAdvDataIsConnectable": 1, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataLocalName": FF2_5C0E2799, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801e03f0>(
6E400001-B5A3-F393-E0A9-E50E24DCCA9E
)
]
10:08:26.512 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:FF2_5C0E2799, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:26.559 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataIsConnectable": 1, "kCBAdvDataTimestamp": 721850906.557611, "kCBAdvDataRxPrimaryPHY": 129]
10:08:26.560 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:CE-C02DV5LXMD6R, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:26.592 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataTimestamp": 721850906.589628, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataIsConnectable": 0, "kCBAdvDataRxSecondaryPHY": 0]
10:08:26.595 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataTimestamp": 721850906.594036, "kCBAdvDataIsConnectable": 1, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801e04e0>(
FFFF
)
, "kCBAdvDataManufacturerData": <ba040300 83000d01 32333431 43525830 34353238>]
10:08:26.596 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:DSS, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:26.598 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataTimestamp": 721850906.594072, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801a2f10>(
FFFF
)
, "kCBAdvDataManufacturerData": <ba040300 83000d01 32333431 43525830 34353238 10023003 fd3f5436 4a3f773c ebf61400 00000000 00000000 000000>, "kCBAdvDataIsConnectable": 1, "kCBAdvDataRxSecondaryPHY": 0]
10:08:26.599 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:DSS, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:26.667 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataTimestamp": 721850906.66544, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801b0540>(
802A0000-4EF4-4E59-B573-2BED4A4AC159
)
, "kCBAdvDataIsConnectable": 1, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataManufacturerData": <4000006c 02>]
10:08:26.668 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:ET-2800 Series, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:26.752 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801aa910>(
03FE
)
, "kCBAdvDataIsConnectable": 1, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataServiceData": {
03FE = {length = 18, bytes = 0x017110020001010000000000000000000000};
}, "kCBAdvDataTimestamp": 721850906.75098, "kCBAdvDataRxPrimaryPHY": 129]
10:08:26.753 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:Lenovo Smart Dock 27AFC5, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:26.755 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataServiceData": {
03FE = {length = 18, bytes = 0x017110020001010000000000000000000000};
}, "kCBAdvDataTimestamp": 721850906.753227, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801e4750>(
03FE
)
, "kCBAdvDataLocalName": Lenovo Smart Dock 27AFC5, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataIsConnectable": 1]
10:08:26.756 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:Lenovo Smart Dock 27AFC5, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:27.171 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataIsConnectable": 1, "kCBAdvDataManufacturerData": <4000006b 02>, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataTimestamp": 721850907.170355, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801e3720>(
802A0000-4EF4-4E59-B573-2BED4A4AC159
)
]
10:08:27.173 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:ET-4800 Series, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:27.178 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataLocalName": ET-2800 Series, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataManufacturerData": <4000006c 02>, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801b9380>(
802A0000-4EF4-4E59-B573-2BED4A4AC159
)
, "kCBAdvDataIsConnectable": 1, "kCBAdvDataTimestamp": 721850907.177012]
10:08:27.179 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:ET-2800 Series, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:27.410 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataServiceData": {
1826 = {length = 3, bytes = 0x012000};
}, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801b9890>(
1826,
Cycling Speed and Cadence,
1818
)
, "kCBAdvDataManufacturerData": <f400cc86 ec98832b 01>, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataIsConnectable": 0, "kCBAdvDataTimestamp": 721850907.408365]
10:08:27.411 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:C9/C10-832B, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:27.412 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataLocalName": C9/C10-832B, "kCBAdvDataServiceUUIDs": <__NSArrayM 0x2801b0540>(
1826,
Cycling Speed and Cadence,
1818
)
, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataTxPowerLevel": 0, "kCBAdvDataManufacturerData": <f400cc86 ec98832b 01>, "kCBAdvDataIsConnectable": 0, "kCBAdvDataServiceData": {
1826 = {length = 3, bytes = 0x012000};
}, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataTimestamp": 721850907.4103431]
10:08:27.414 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:C9/C10-832B, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:27.810 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataIsConnectable": 1, "kCBAdvDataTimestamp": 721850907.808724, "kCBAdvDataRxPrimaryPHY": 129]
10:08:27.812 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:CE-C02DV5LXMD6R, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:28.039 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataIsConnectable": 0, "kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataTimestamp": 721850908.038304, "kCBAdvDataRxPrimaryPHY": 129]
10:08:31.030 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataRxPrimaryPHY": 129, "kCBAdvDataIsConnectable": 1, "kCBAdvDataTimestamp": 721850911.028445]
10:08:31.031 | ESPDevice.init(name:security:transport:proofOfPossession:username:softAPPassword:advertisementData:) (149) : Intializing ESPDevice with name:CE-C02DV5LXMD6R, security:secure, transport:ble, proofOfPossession:nil and softAPPassword:nil
10:08:31.387 | ESPBleTransport.centralManager(:didDiscover:advertisementData:rssi:) (274) : Peripheral devices discovered.["kCBAdvDataRxSecondaryPHY": 0, "kCBAdvDataIsConnectable": 0, "kCBAdvDataTimestamp": 721850911.384437, "kCBAdvDataRxPrimaryPHY": 129]
10:08:31.462 | ESPBleTransport.stopScan(timer:) (214) : Ble scan stopped.
10:08:31.464 | ESPProvisionManager.peripheralsFound(peripherals:) (352) : Ble devices found :["FF2_5C0E2799": ESPProvision.ESPDevice, "C9/C10-832B": ESPProvision.ESPDevice, "ET-2800 Series": ESPProvision.ESPDevice, "DSS": ESPProvision.ESPDevice, "ET-4800 Series": ESPProvision.ESPDevice, "CE-C02DV5LXMD6R": ESPProvision.ESPDevice, "Lenovo Smart Dock 27AFC5": ESPProvision.ESPDevice]
2023-11-16T10:08:31-0800 debug device-assistant : [DeviceAssistant] found devices
2023-11-16T10:08:31-0800 debug device-assistant : [DeviceAssistant] Parsing message from byte data [3, 0, 131, 0]
2023-11-16T10:08:31-0800 debug device-assistant : [DeviceAssistant] Parsing message from byte data [13, 1, 50, 51, 52, 49, 67, 82, 88, 48, 52, 53, 50, 56]
2023-11-16T10:08:31-0800 debug device-assistant : [DeviceAssistant] Parsing message from byte data [16, 2, 48, 3, 253, 63, 84, 54, 74, 63, 119, 60, 235, 246, 20, 0, 0]
2023-11-16T10:08:31-0800 debug device-assistant : [DeviceAssistant] message data: [48, 3, 253, 63, 84, 54, 74, 63, 119, 60, 235, 246, 20, 0, 0]
2023-11-16T10:08:31-0800 debug device-assistant : [DeviceAssistant] Found the device
10:08:35.788 | ESPDevice.connect(delegate:completionHandler:) (165) : Connecting ESPDevice...
10:08:35.789 | ESPDevice.connect(delegate:completionHandler:) (169) : Start connecting ble device.
10:08:35.790 | ESPBleTransport.connect(peripheral:withOptions:delegate:) (159) : Connecting peripheral device...
10:08:35.791 | ESPBleTransport.connect(peripheral:withOptions:delegate:) (169) : Initiating timeout for connection completion.
10:08:36.222 | ESPBleTransport.centralManager(:didConnect:) (285) : Connected to peripheral. Discover services.
10:08:36.637 | ESPBleTransport.peripheral(:didDiscoverServices:) (304) : Peripheral did discover services.
10:08:36.758 | ESPBleTransport.peripheral(:didDiscoverCharacteristicsFor:error:) (315) : Peripheral did discover chatacteristics.
10:08:36.762 | ESPBleTransport.peripheral(:didDiscoverDescriptorsFor:error:) (358) : Did sicover descriptor for characterisitic: <CBCharacteristic: 0x282bd02a0, UUID = FF01, properties = 0x8, value = (null), notifying = NO>
10:08:36.877 | ESPBleTransport.peripheral(:didDiscoverDescriptorsFor:error:) (358) : Did sicover descriptor for characterisitic: <CBCharacteristic: 0x282bd0120, UUID = FF02, properties = 0x12, value = (null), notifying = NO>
10:08:36.936 | ESPBleTransport.peripheral(:didUpdateValueFor:error:) (365) : Did update value for descriptor: <CBDescriptor: 0x2801b05a0, UUID = Client Characteristic Configuration, value = (null)>
10:08:55.793 | ESPBleTransport.bleConnectionTimeout() (176) : Peripheral connection timeout occured.
10:08:55.794 | ESPBleTransport.disconnect() (186) : Cancelling peripheral connection.
10:08:55.796 | ESPDevice.peripheralFailedToConnect(peripheral:error:) (661) : Peripheral failed to connect.
2023-11-16T10:08:55-0800 error device-assistant : [DeviceAssistant] Device failed to connect: Failed to connect with BLE device
2023-11-16T10:09:51-0800 debug device-assistant : [DeviceAssistant] failed to connect to peripheral
10:09:51.433 | ESPBleTransport.centralManager(_:didDisconnectPeripheral:error:) (295) : Disconnected with peripheral
10:09:51.434 | ESPDevice.peripheralDisconnected(peripheral:error:) (654) : Peripheral disconnected.
2023-11-16T10:09:52-0800 debug device-assistant : [DeviceAssistant] peripheral disconnected

Additional context
Add any other context about the problem here.

[bpfingsten-crestron]

So after some review of the library code I see that its requiring a descriptor to be returned for each characteristic before it changes state to connected and my FF01 characteristic is not responding with a descriptor. ESPBleTransport::func peripheral(_: CBPeripheral, didUpdateValueFor descriptor: CBDescriptor, error _: Error?) is the function involved and does the state change to connected or at least it kills the timer and signals the connected state.

[vikas-chandra-mnnit]

Hi @bpfingsten-crestron, your observation is accurate. The SDK attempts to read the value for each descriptor in a characteristic, after which it propagates the BLE connection successful message. A 20-second timer is established for this process, and if not completed, the connection terminates. Please feel free to reach out if you require additional assistance on this matter.