NimBLE-Arduino: Hang at disconnect during notify

I’m trying to use NimBLE-arduino in Tasmota, and having an issue with an unrecoverable BLE hang.

Basically, I have: a single client.

I then 1/ stop a scan 2/ connect by MAC 3/ get a service 4/ get a characteristic (for read/write use) 5/ get a characteristic for notify. 6/ subscribe for notify 7/ write to the read/write characteristic.

All Initialisation and operation of BLE is performed from a single Task (separate from the main task in Tasmota).

this works a lot of the time. But often, I see logs like the below.

basically, after the notification comes in, a little later (~1s) I disconnect. But the disconnect does not seem to be successful, and client->isConnected() remains true.

After this, I can’t do anything with BLE, it seems broken. I can’t even ::deinit and ::init - my only option is reboot.

sometimes it is associated with an earlier occurence of the log:

lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)

Any advice as to how to avoid this, or further diagnose?

I have tried with ESP32 Arduino 1.0.4 (IDF 3.2) Release and latest git. behaviour seems similar.

in the log below ‘…’ indicates where I’ve remove http related sections, and ‘>>’ indicates comments I have added.

br, Simon

D NimBLEScan: ">> stop()"
D NimBLEScan: "<< stop()"
22:50:52 SL4-26 runCurrentOperation: new currentOperation
22:50:52 SL3-27 Scan ended
22:50:52 SL2-28 MI32: scancomplete
22:50:52 SL1-29 scancompleteCallbacks 0 0
22:50:52 MQT: tele/tasmota_esp32/BLE = {"active":{"5FD2D49DE1D7":{"n":""},"2D82E35C7469":{"n":""},"743E6283EA71":{"n":""},"1D1151D65BFF":{"n":""},"001A22092C9A":{"n":"CC-RT-M-BLE"},"001A22092CDB":{"n":"CC-RT-M-BLE"},"001A22092FB7":{"n":"CC-RT-M-BLE"}}}
D NimBLEClient: ">> connect(00:1a:22:09:2f:b7)"
D NimBLEScan: ">> stop()"
D NimBLEScan: "<< stop()"
22:50:53 SL1-29 attempt connect 00:1a:22:09:2f:b7
[V][WebServer.cpp:291] handleClient(): New client
[V][Parsing.cpp:113] _parseRequest(): method: GET url: / search: m=1
.....
[V][Parsing.cpp:231] _parseRequest():  Arguments: m=1
[V][WebServer.cpp:291] handleClient(): New client
D NimBLEClient: "Got Client event "
D NimBLEClient: "Connection established"
[V][Parsing.cpp:113] _parseRequest(): method: GET url: / search: m=1
.....
[V][Parsing.cpp:220] _parseRequest(): headerValue: http://192.168.1.212/?
D NimBLECl[V][Parsing.cpp:219] _parseRequest(): headerName: Accept-Encoding
ie[V][Parsing.cpp:220] _parseRequest(): headerValue: gzip, deflate
nt: "Got Client[V][Parsing.cpp:219] _parseRequest(): headerName: Accept-Language
[V][Parsing.cpp:220] _parseRequest(): headerValue: en-US,en;q=0.9,en-GB;q=0.8,fr;q=0.7
 e[V][Parsing.cpp:247] _parseArguments(): args: m=1
ve[V][Parsing.cpp:265] _parseArguments(): args count: 1
n[V][Parsing.cpp:273] _parseArguments(): pos 0 =@1 &@-1
t [V][Parsing.cpp:284] _parseArguments(): arg 0 key: m value: 1
[V][Parsing.cpp:291] _parseArguments(): args count: 1
"
[V][Parsing.cpp:230] _parseRequest(): Request: /
[V][Parsing.cpp:231] _parseRequest():  Arguments: m=1
D NimBLEClient: "Peer requesting to update connection parameters"
>> what does this mean?

D NimBLEClient: "MinInterval: 40, MaxInterval: 200, Latency: 0, Timeout: 5000"
D NimBLEClient: "Rejected peer params"
D NimBLEClient: "Got Client event "
I NimBLEClient: "mtu update event; conn_handle=0 mtu=23"
D NimBLEClient: ">> deleteServices"
D NimBLERemoteService: ">> deleteCharacteristics"
D NimBLERemoteCharacteristic: ">> deleteDescriptors"
D NimBLERemoteCharacteristic: "<< deleteDescriptors"
D NimBLERemoteCharacteristic: ">> deleteDescriptors"
D NimBLERemoteCharacteristic: "<< deleteDescriptors"
D NimBLERemoteService: "<< deleteCharacteristics"
D NimBLEClient: "<< deleteServices"
>> delayed log.....
22:50:58 SL1-29 onConnParamsUpdateRequest 00:1a:22:09:2f:b7
D NimBLEClient: "<< connect()"
D NimBLEClient: ">> getService: uuid: 3e135142-654f-9090-134a-a6ff5bb77046"
D NimBLEClient: ">> retrieveServices"
22:50:58 SL2-28 onConnect 00:1a:22:09:2f:b7
22:50:58 SL1-29 connected 00:1a:22:09:2f:b7 - will getservice
D NimBLEClient: "Service Discovered >> status: 0 handle: 1024"
D NimBLERemoteService: ">> NimBLERemoteService()"
D NimBLERemoteService: "<< NimBLERemoteService()"
D NimBLEClient: "Service Discovered >> status: 14 handle: -1"
D NimBLEClient: "<< << Service Discovered"
D NimBLEClient: "<< retrieveServices"
D NimBLERemoteService: ">> retrieveCharacteristics() for service: 3e135142-654f-9090-134a-a6ff5bb77046"
22:50:58 SL1-29 got service
D NimBLERemoteService: "Characteristic Discovered >> status: 0 handle: 1041"
D NimBLERemoteService: "Characteristic Discovered >> status: 14 handle: -1"
D NimBLERemoteService: "<< Characteristic Discovered"
D NimBLERemoteService: "<< retrieveCharacteristics()"
D NimBLERemoteService: ">> retrieveCharacteristics() for service: 3e135142-654f-9090-134a-a6ff5bb77046"
D NimBLERemoteService: "Characteristic Discovered >> status: 0 handle: 1057"
D NimBLERemoteService: "Characteristic Discovered >> status: 14 handle: -1"
D NimBLERemoteService: "<< Characteristic Discovered"
D NimBLERemoteService: "<< retrieveCharacteristics()"
D NimBLERemoteCharacteristic: ">> setNotify(): Characteristic: uuid: d0e8434d-cd29-0996-af41-6c90f4e0eb2a, handle: 1057 0x0421, props:  0x1a, 01"
D NimBLERemoteCharacteristic: ">> getDescript22:50:59 SL1-29 got notify characteristic
or: uuid: 0x2902"
D NimBLERemoteCharacteristic: ">> retrieveDescriptors() for characteristic: d0e8434d-cd29-0996-af41-6c90f4e0eb2a"
D NimBLERemoteCharacteristic: "Descriptor Discovered >> status: 0 handle: 1072"
D NimBLERemoteCharacteristic: "Descriptor Found"
D NimBLERemoteCharacteristic: "<< Descriptor Discovered. status: 0"
D NimBLERemoteCharacteristic: "<< setNotify()"
D NimBLERemoteDescriptor: ">> Descriptor writeValue: Descriptor: uuid: 0x2902, handle: 1072"
D NimBLERemoteCharacteristic: ">> writeValue(), length: 1"
22:50:59 SL2-28 subscribe for notify
22:50:59 SL1-29 got read/write characteristic
I NimBLERemoteCharacteristic: "Write complete; status=0 conn_handle=0"
D NimBLERemoteCharacteristic: "<< writeValue, rc: 0"
22:50:59 SL1-29 write characteristic
D NimBLEClient: "Got Client event "
D NimBLEClient: "Notify Recieved for handle: 1057"
D NimBLEClient: "checking service 3e135142-654f-9090-134a-a6ff5bb77046 for handle: 1057"
D NimBLEClient: "Got Notification for characteristic Characteristic: uuid: d0e8434d-cd29-0996-af41-6c90f4e0eb2a, handle: 1057 0x0421, props:  0x1a
Descriptor: uuid: 0x2902, handle: 1072"
D NimBLEClient: "Invoking callback for notification on characteristic Characteristic: uuid: d0e8434d-cd29-0996-af41-6c90f4e0eb2a, handle: 1057 0x0421, props:  0x1a
Descriptor: uuid: 0x2902, handle: 1072"
22:50:59 SL1-29 Notified length: 6
D NimBLEClient: ">> disconnect()"
D NimBLEClient: "<< disconnect()"
22:51:00 SL2-28 notify operation complete

>> delayed log - probably cause the dicsonnect above...

22:51:00 SL1-29 runTaskDoneOperation: disconnecting connected client
[V][WebServer.cpp:291] handleClient(): New client
[V][Parsing.cpp:113] _parseRequest(): method: GET url: / search: m=1
[V][Parsing.cpp:219] _parseRequest(): headerName: Host
.....
[V][Parsing.cpp:231] _parseRequest():  Arguments: m=1
>> log indicates client->isConnected() returns true! ????
22:51:01 SL1-29 wait disconnect 1
22:51:01 MQT: tele/tasmota_esp32/SENSOR = {"Time":"2020-12-08T22:51:01","IBEACON":{"MAC":"001A22092C9A","NAME":"CC-RT-M-BLE","RSSI":0,"STATE":"OFF"}}
D NimBLEClient: ">> disconnect()"
E NimBLEClient: "ble_gap_terminate failed: rc=2 "
D NimBLEClient: "<< disconnect()"
22:51:02 SL2-28 wait disconnect 2
>> cause of disconnect above..  but is_connected() is still true.....
22:51:02 SL1-29 retry disconnect 3
22:51:02 WIF: Checking connection...
22:51:02 SL1-29 wait disconnect 3
22:51:03 SL1-29 wait disconnect 4
22:51:03 SL0-30 wait disconnect 5
22:51:03 SL1-29 BLE Failed, restarting Tasmota
[V][WebServer.cpp:291] handleClient(): New client
[V][Parsing.cpp:113] _parseRequest(): method: GET url: / search: m=1
....
[V][Parsing.cpp:231] _parseRequest():  Arguments: m=1
22:51:04 BLE Failure! Restarting in 5s
D NimBLEClient: ">> disconnect()"
E NimBLEClient: "ble_gap_terminate failed: rc=2 "
D NimBLEClient: "<< disconnect()"
D NimBLEClient: ">> disconnect()"
E NimBLEClient: "ble_gap_terminate failed: rc=2 "
D NimBLEClient: "<< disconnect()"