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.

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://<IP_ADDRESS>/?
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()"

hmm...  looks like we are missing 'D NimBLEClient: "Got Client event "' for that disconnect.  I.e. BLE does not give us a disconnect?
Also, just tested with write only, and it still fails (no notify requested).

Hi @btsimonh, yes it seems the event is not being triggered. I'll see if I can reproduce this. Thanks for reporting.

When you call disconnect do you perform any delay? Ideally you should wait until the disconnect completes which will trigger the callback.

the disconnect code is below.
It feels like it is a lot worse with heavier Wifi traffic.
Is there a wifi config I could be missing which enables time switching between BLE and Wifi on the radio?  I can't find anything in the ESP documentation about how wifi and BLE can co-exist; just lot's of speculation about a shared radio.
    if ((*ppClient)->isConnected()){
      BLE_ESP32::SafeAddLog_P(LOG_LEVEL_DEBUG,PSTR("runTaskDoneOperation: disconnecting connected client"));
      (*ppClient)->disconnect();
      // wait for 1/2 second after disconnect
      int waits = 0;
      do {
        vTaskDelay(500/ portTICK_PERIOD_MS);
        if (waits) BLE_ESP32::SafeAddLog_P(LOG_LEVEL_ERROR,PSTR("wait disconnect %d"), waits);
        waits++;
        if (waits == 3){
          // try again?
          if (waits) BLE_ESP32::SafeAddLog_P(LOG_LEVEL_ERROR,PSTR("retry disconnect %d"), waits);
          (*ppClient)->disconnect();
        }
        if (waits == 6){
          // try again?
          BLE_ESP32::SafeAddLog_P(LOG_LEVEL_ERROR,PSTR("BLE Failed, restarting Tasmota"));
          BLEStop = 1;
          BLERestartTasmota = 5;
          return;
        }
      } while ((*ppClient)->isConnected());

just looking through the code, one thing I notice is use of 1ms delays, e.g.:
        if(rc == BLE_HS_EBUSY) {
            vTaskDelay(1 / portTICK_PERIOD_MS);
        }

from here https://github.com/espressif/arduino-esp32/issues/2981 it seems this will not give up the timeslice.
Suggest if the timeslice should be given up, that a minimum delay would be vTaskDelay(1); with a comment for reasoning.
(I did get an idle task watchdog restart once, naming 'btController' as the task in progress....).
BUT, I changed all of them in NimBLE to vTaskDelay(1), and the problem persists, so this is not the cause.

even more detailed log here:
https://gist.github.com/btsimonh/d9b4bc7a12e8ab81c4adb9b999d4b425
in this log, I stall at the point of failure by staying in the above while loop with an additional vTaskDelay of 5s per loop.
I've included quite some time after the failure - there is nothing more from BLE low level after it stops -i.e. looks like it never got the disconnect packet?
p.s. I added the two changes in esp_nimble vs. the version in arduino-nimble - but no improvement. (e.g. a PR addressing a stack overflow due to recursion).

raised an issue here:
https://github.com/apache/mynewt-nimble/issues/890
I think there should be some timeout on not receiving the terminate confirmation - but I don't know if this should be in mynewt or in arduino-nimble.  Is there some way to force the connection to abort, so that we could put a timeout inside or outside of arduino-nimble?

I've added the ability to reset the BLE stack through NimBLE device as a test - it ran through it's first iteration a few minutes ago; let's see how many resets it can survive.  May be a good belt-and-braces thing to add anyway....

I've done some testing and have not been able to reproduce this issue. Looking at the log it seems the disconnect is occurring but the callback is not triggered. This comes when the controller returns the event to the host, which it seems does not happen.
I see you are performing some wifi operations in the time that BLE is working. This could be the source of the issue. Since the controller is closed source we don't have access to debug at that point sadly. I suggest for testing to remove the wifi code and run BLE only to check if the issue still occurs.

hmm..
I'm also convinced that wifi makes it worse, but I can't easily stop it using wifi - the writes are triggered over MQTT.... and Tasmota is quite a complex project.
I'm also talking to possibly particularly bad BLE devices - EQ3 radiator valves based on dubious hardware.
BLE transactions are so complex and so variable, I'm not surprised that you could not reproduce.
But at the moment, I can't see anything in mynewt or NimBLE designed to cope with a disconnect timeout.  So I think this should be added.  At what level, i'm not sure.
I will fork the repo, and push a branch with my current changes, which are so far successful in restoring operation - maybe they will be a good discussion point.

hi @h2zero,
these are the changes I made to enable reset of the BLE stack when stuck....
https://github.com/h2zero/NimBLE-Arduino/compare/master...btsimonh:btsimonh-test
The reset restores operation, but I'm seeing crashes too...  I'll monitor better tomorrow (too many logs to catch the crash...)

I don't think it should be necessary to reset the host. There is something else happening that shouldn't be and would be better if we could find that.
The disconnect code you shared, is that in your notification callback handler? That could be a source of trouble, delays used in the callback will stuff things up.

no, I'm not even asking for notify for this testing..  only write.  And the notify callback has been stripped to the bone, just noting that it happened and capturing the data (did this after I found that the notify cb could occur BEFORE the write returned - even though the write is necessary to trigger the notify!!! - so I must subscribe and then write, but be able to catch the notify response before the write is officially over....  two days ago I thought the issue could be related to the write/notify timing; maybe it is but at a lower level? - but now I'm testing with write only....
(
some stupid thoughts around this.... I observed notify hitting me before the write function completed in at least two of the previous failures.  Now I am only writing to remove this as a failure mode.  BUT.  is it possible that the device ALWAYS sends a notify packet when it gets a write - or has somehow remembered that I requested notify ONCE, and so is sending one?  And what if this packet REALLY arrives during the write packet sequence, not after, just sometimes?  I know nothing about BLE packet sequences, so it's just a thought.
-- in the log in the gist above... my request command is (line 582):
Data "m:001A22092FB7 s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 w:03 u:581046 go"
-- I am NOT requesting notify (would be n:xxxxx)
but...  at line 572, we DO receive a notification at a low level.
BUT..  the log looks no different to a successful transaction, until it just does not get the disconnect callback to NimbleClient.
log containing success: https://gist.github.com/btsimonh/dd96853159594216d66addebf611b3a7
)
Ref reset() - I wanted to test if it was a hardware thing or if the stack could proceed...  I still think it's a good addition to arduino-nimble, as in the failed situation, deleteClient() refuses to delete because it believes it's connected, so you have no way out.  I didn't try yet just deleting and recreating the dead client - I am guessing that the connected handle needs disposing of somehow in the myNewt, and could not work out the best way to do that, hence the reset which should do it (in a sledgehammer kind of way) .... and deinit(), init() similarly did not do the job in a previous test probably because it could not delete the client?.
I pushed a branch with my current test code:
https://github.com/btsimonh/Tasmota/blob/Tasmota/BLE_TEMP/tasmota/xdrv_47_BLE_ESP32.ino
ALL the BLE code is run from a single task (I was running some from main thead, but moved it all into a single task because i was concerned it could be a cross-thread thing, but it seems not).
BLEOperationTask  is the task.
It runs runCurrentOperation once per second at most.  If no operation is in progress, it starts a 20s scan.
BLESensorCallback is the client callback class, and only logs.
when an operation is 'complete' (for write, this just means 'when we finished writing'), the next runCurrentOperation (1s later) will trigger runTaskDoneOperation, which removes the current operation, and disconnects if the client is not disconnected.  This is now the only normal disconnect (I don't leave the task, which is the only other disconnect() in the code).
Testing specifics:
I usually have 2-3 devices n range which I'm trying to talk to, plus another 3-4 which are providing adverts only.
Example:
If I see 3 devices in range of the required type, I will cycle through them, issuing a write command and waiting for a result.
'normally' at least one of the three is not close enough for a reliable connection, so I see a failure of some sort, either a failure to connect, or a failure of some part of the write process.  in this case, I get a fail result, disconnect, and move on.
A new write is triggered when the external device has received the Success/fail, so normally there is a 2-5 seconds of scan before the next request.
What I will try to do today if I get time:
I'm currently driving Tasmota via MQTT.  I may be able to disconnect the MQTT, and not connect a webpage to Tasmota, and this would reduce network traffic significantly (down to wifi maintenance packets only), and I will attempt to create a Node-Red flow which drives it over serial, and also captures the logs looking for failures and reboots.  My biggest problem at the moment is that VSCode/PIO only has so much scrollback stored, so I have to sit and watch for a failure to catch, and then manipulate VSCode rather quickly before that failure's logs are lost! :).

with only one EQ3 visible (and at fairly close range), it's run faultlessly for ages.  Even with the network traffic.
I've also INCREASED the network traffic by logging to MQTT, and it's still running nicely.
I moved the ESP32 so that it got a sniff of a second device, and it seemed ok (a sniff to see it, but always failure to connect).
When I introduced a 3rd device (very close range, new batteries), it failed quite quickly afterwards.  (the failure was against the device which it had been talking to quite well - (229 successful writes vs 21 failure to connect).

but also a new type of failure, logged here:
https://gist.github.com/btsimonh/1ec22e96051a98efe8c4202543782727
after line 2699, BLE logs next a disconnect at 3481 (90 seconds), and then nothing.
This seems to be stuck in the client->connect() call...
at line 2681 in the log, this seems missing:
D NimBLEClient: "Connection established"
GATT procedure initiated: exchange mtu
host tx hci data; handle=0 length=7
ble_hs_hci_acl_tx(): 0x00 0x00 0x07 0x00 0x03 0x00 0x04 0x00 0x02 0x00 0x01
txed att command: mtu req; conn=0 mtu=256

It is as though these lines in client happened:
        case BLE_GAP_EVENT_CONNECT: {
            if(!client->m_waitingToConnect)
                return 0;

Maybe BLE_GAP_EVENT_CONNECT came in before you set m_waitingToConnect = true?  if it did, it's stuck in the ulTaskNotifyTake() :(.
I'll rebuild with the m_waitingToConnect = true before the ble subsystem call.... and add some more diags around this point and the disconnect point.

I think I have an answer for this. I should have noticed this earlier but in your log here you can see that the supervision timeout is set to 50 seconds(5000 x 10ms).
So when you send the disconnect command in your busy environment the acknowledgement packet from the peripheral may not be received, which the controller will then resort to waiting for the timeout to expire before triggering the event and callback.  Try setting that to 200 instead and see if it resolves your issue.

will change that and let you know.  At least I now have monitoring which highlights issues, and all logs stored on disk :).
?? you mean in onConnParamsUpdateRequest I should reject the proposed params?  e.g.:
    if(params->itvl_min < 24) { /** 1.25ms units */
      return false;
    } else if(params->itvl_max > 40) { /** 1.25ms units */
      return false;
    } else if(params->latency > 2) { /** Number of intervals allowed to skip */
      return false;
    } else if(params->supervision_timeout > 200) { /** 10ms units */
      return false;
    }

some stupid thoughts around this.... I observed notify hitting me before the write function completed in at least two of the previous failures. Now I am only writing to remove this as a failure mode. BUT. is it possible that the device ALWAYS sends a notify packet when it gets a write - or has somehow remembered that I requested notify ONCE, and so is sending one? And what if this packet REALLY arrives during the write packet sequence, not after, just sometimes? I know nothing about BLE packet sequences, so it's just a thought.

There are a few off the shelf devices out there that just start sending notifications as soon as a connection is established, regardless of whether the client subscribed or not.

you mean in onConnParamsUpdateRequest I should reject the proposed params? e.g.:

if(params->itvl_min < 24) { /** 1.25ms units */
  return false;
} else if(params->itvl_max > 40) { /** 1.25ms units */
  return false;
} else if(params->latency > 2) { /** Number of intervals allowed to skip */
  return false;
} else if(params->supervision_timeout > 200) { /** 10ms units */
  return false;
}

and/or should I change:
pClient->setConnectionParams(12,12,0,51);

I would just use pClient->setConnectionParams(12,12,0,51); and reject the update request from the peripheral if it comes. That should force the disconnect to happen within 510ms.

ok, started another run.  (also with moved m_waitingToConnect = true).

a few more additions pushed in https://github.com/btsimonh/NimBLE-Arduino/tree/btsimonh-test

sorry about this, but it all contributes.  Another BLE hang.  This time, it may highlight the cause:
https://gist.github.com/btsimonh/2a190e696883a6e68633a1053c0947c4
My read of the code indicates that  in this case ble_hs_hci_lock() was not released somewhere.
at line 1619, we enter disconnect() - but we never leave....
But it does tell us it's started disconnect, so must have got as far as calling ble_gap_terminate - but if you check my repo, I have logs in both exits for that, and neither show, plus never << disconnect :(.
Where can we go from there?

and an unhandled exception; interesting one:
https://gist.github.com/btsimonh/da1683dd2c7ab1da10e91284d4fbf489
(line 1700 onwards.   really odd one).

and another :(
https://gist.github.com/btsimonh/de15d7345c3ce99077b5f2d71e59bbba
just go to the end

Looks like the controller is hanging. What I think happens is it's command cache gets overwritten so it loses track of the commands. I have seen this type of behavior before and it's very difficult to debug since that is closed source. One of the more recent commits in the controller repo addresses an endless loop bug and it looks like you are hitting that bug. Another possibility is since your ble code is running on core 0 it could be interfering, try changing the core for that task to 1.

I did initially try the dev version of the esp framework, but i think i'm back on the release now.
Started a new run on core 1.....

no banana on core 1.
stalled in WriteValue:
NimBLEScan: "UPDATING PREVIOUSLY FOUND DEVICE: 4c:65:a8:da:f6:07"
D NimBLEAdvertisedDevice: "payload: 09094d4a5f48545f563105030f180a180916fffff37c8b273515"
LE advertising report. len=42 num=1 evtype=3 addrtype=1 addr=34.95.30.bc.30.3e advlen=31 rssi=-56
1e ff 06 00 01 09 20 02
D NimBLEClient: ">> connect(00:1a:22:09:2c:db)"
D NimBLEScan: ">> stop()"
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000c len=2
21:46:46 MQT: tele/tasmota_d0 8c 93 54 45 b8 28 c6
0x0c 0x20 0x02 0x00 0x00
21:46:46 SL8-22 MI32Command complete: cmd_pkts=5 ogf=0x8 ocf=0xc status=0
Adv: svcdata70 82d2 2f229 e220 39 c2 db 7e
1b bb d5 d0 14 f0 85
D NimBLEScan: "<< stop()"
GAP procedure initiated: connect; peer_addr_type=0 peer_addr=00:1a:22:09:2c:db scan_itvl=16 scan_window=16 itvl_min=12 itvl_max=12 latency=0 supervision_timeout=51 min_ce_len=0 max_ce_len=0 own_addr_type=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000d len=25
0x0d 0x20 0x19 0x10 0x00 0x10 0x00 0x00 0x00 0xdb 0x2c 0x09 0x22 0x1a 0x00 0x00 0x0c 0x00 0x0c 0x00 0x00 0x00 0x33 0x00 0x00 0x00 0x00 0x00
Command Status: status=0 cmd_pkts=5 ocf=0xd ogf=0x8
21:46:46 SL3-27 Scan ended
21:46:46 SL2-28 MI32: scancomplete
21:46:46 SL1-29 scancompleteCallbacks 0 0
LE connection complete. handle=0 role=0 paddrtype=0 addr=0.1a.22.9.2c.db local_rpa=<IP_ADDRESS>.0.0 peer_rpa=<IP_ADDRESS>.0.0 itvl=12 latency=0 spvn_tmo=51 mca=0
D NimBLEClient: "Got Client event "
D NimBLEClient: "Connection established"
GATT procedure initiated: exchange mtu
host tx hci data; handle=0 length=7
ble_hs_hci_acl_tx(): 0x00 0x00 0x07 0x00 0x03 0x00 0x04 0x00 0x02 0x00 0x01
txed att command: mtu req; conn=0 mtu=256
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x0016 len=2
0x16 0x20 0x02 0x00 0x00
Command Status: status=0 cmd_pkts=5 ocf=0x16 ogf=0x8
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=16 data=0x0c 0x00 0x05 0x00 0x12 0x77 0x08 0x00 0x28 0x00 0xc8 0x00 0x00 0x00 0x88 0x13
L2CAP - rxed signalling msg: 0x12 0x77 0x08 0x00 0x28 0x00 0xc8 0x00 0x00 0x00 0x88 0x13
D NimBLEClient: "Got Client event "
D NimBLEClient: "Peer requesting to update connection parameters"
D NimBLEClient: "MinInterval: 40, MaxInterval: 200, Latency: 0, Timeout: 5000"
D NimBLEClient: "Rejected peer params"
host tx hci data; handle=0 length=10
ble_hs_hci_acl_tx(): 0x00 0x00 0x0a 0x00 0x06 0x00 0x05 0x00 0x13 0x77 0x02 0x00 0x01 0x00
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=7 data=0x03 0x00 0x04 0x00 0x03 0x17 0x00
rxed att command: mtu rsp; conn=0 mtu=23
D NimBLEClient: "Got Client event "
I NimBLEClient: "mtu update event; conn_handle=0 mtu=23"
D NimBLEClient: ">> deleteServices"
D NimBLERemoteService: ">> deleteCharacteristics"
D NimBLERemoteCharacteristic: ">> deleteD21:46:46 SL1-29 onConnParamsUpdateRequest 00:1a:22:09:2c:db
escriptors"
D NimBLERemoteCharacteristic: "<< deleteDescriptors"
D NimBLERemoteService: "<< deleteCharacteristics"
D NimBLEClient: "<< deleteServices"
D NimBLEClient: "<< connect()"
D NimBLEClient: ">> getService: uuid: 3e135142-654f-9090-134a-a6ff5bb77046"
D NimBLEClient: ">> retrieveServices"
GATT procedure initiated: discover service by uuid; uuid=3e135142-654f-9090-134a-a6ff5bb77046
txed att command: find type value req; conn=0 start_handle=0x0001 end_handle=0xffff attr_type=10240
LE Remote Used Features. handle=0 feat=01 00 00 00 00 00 00 00
host tx hci data; handle=0 length=27
ble_hs_hci_acl_tx(): 0x00 0x00 0x1b 0x00 0x17 0x00 0x04 0x00 0x06 0x01 0x00 0xff 0xff 0x00 0x28 0x46 0x70 0xb7 0x5b 0xff 0xa6 0x4a 0x13 0x90 0x90 0x4f 0x65 0x42 0x51 0x13 0x3e
Number of Completed Packets: num_handles=1
handle:0 pkts:1
21:46:46 SL2-28 onConnect 00:1a:22:09:2c:db
21:46:46 SL1-29 connected 00:1a:22:09:2c:db - will getservice
21:46:46 MQT: tele/tasmota_esp32/BLE = {"active":{"001A22092CDB":{"n":"CC-RT-M-BLE"},"4C65A8DAF607":{"n":"MJ_HT_V1"},"001A22092FB7":{"n":"CC-RT-M-BLE"},"4C65A8DAF43A":{"n":"MJ_HT_V1"},"6662A3A9B6FC":{"n":""},"43455021FD69":{"n":""},"349530BC303E":{"n":""},"15D80AB7CDB3":{"n":""},"001A22092C9A":{"n":"CC-RT-M-BLE"}}}
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x07 0x00 0x04 0x30 0x04
rxed att command: find type value rsp; conn=0
D NimBLEClient: "Service Discovered >> status: 0 handle: 1024"
D NimBLERemoteService: ">> NimBLERemoteService()"
D NimBLERemoteService: "<< NimBLERemoteService()"
txed att command: find type value req; conn=0 start_handle=0x0431 end_handle=0xffff attr_type=10240
host tx hci data; handle=0 length=27
ble_hs_hci_acl_tx(): 0x00 0x00 0x1b 0x00 0x17 0x00 0x04 0x00 0x06 0x31 0x04 0xff 0xff 0x00 0x28 0x46 0x70 0xb7 0x5b 0xff 0xa6 0x4a 0x13 0x90 0x90 0x4f 0x65 0x42 0x51 0x13 0x3e
[V][WebServer.cpp:291] handleClient(): New client
[V][Parsing.cpp:113] _parseRequest(): method: GET url: /cs search: c2=149
[V][Parsing.cpp:219] _parseRequest(): headerName: Host
[V][Parsing.cpp:220] _parseRequest(): headerValue: <IP_ADDRESS>
[V][Parsing.cpp:219] _parseRequest(): headerName: Connection
[V][Parsing.cpp:220] _parseRequest(): headerValue: keep-alive
[V][Parsing.cpp:219] _parseRequest(): headerName: User-Agent
[V][Parsing.cpp:220] _parseRequest(): headerValue: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36
[V][Parsing.cpp:219] _parseRequest(): headerName: DNT
[V][Parsing.cpp:220] _parseRequest(): headerValue: 1
[V][Parsing.cpp:219] _parseRequest(): headerName: Accept
[V][Parsing.cpp:220] _parseRequest(): headerValue: /
[V][Parsing.cpp:219] _parseRequest(): headerName: Referer
[V][Parsing.cpp:220] _parseRequest(): headerValue: http://<IP_ADDRESS>/cs?
Number of[V][Parsing.cpp:219] _parseRequest(): headerName: Accept-Encoding
C[V][Parsing.cpp:220] _parseRequest(): headerValue: gzip, deflate
ompleted Packets[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
nu[V][Parsing.cpp:247] _parseArguments(): args: c2=149
m[V][Parsing.cpp:265] _parseArguments(): args count: 1
_h[V][Parsing.cpp:273] _parseArguments(): pos 0 =@2 &@-1
andl[V][Parsing.cpp:284] _parseArguments(): arg 0 key: c2 value: 149
[V][Parsing.cpp:291] _parseArguments(): args count: 1
es[V][Parsing.cpp:230] _parseRequest(): Request: /cs
[V][Parsing.cpp:231] _parseRequest():  Arguments: c2=149
=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x01 0x06 0x31 0x04 0x0a
rxed att command: error rsp; conn=0 req_op=6 handle=0x0431 error_code=10
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"
GATT procedure initiated: discover characteristics by uuid; start_handle=1024 end_handle=1072 uuid=3fa4585a-ce4a-3bad-db4b-b8df8179ea09
txed att command: read type req; conn=0 start_handle=0x0400 end_handle=0x0430
host tx hci data; handle=0 length=11
ble_hs_hci_acl_tx(): 0x00 0x00 0x0b 0x00 0x07 0x00 0x04 0x00 0x08 0x00 0x04 0x30 0x04 0x03 0x28
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=27 data=0x17 0x00 0x04 0x00 0x09 0x15 0x10 0x04 0x0a 0x11 0x04 0x09 0xea 0x79 0x81 0xdf 0xb8 0x4b 0xdb 0xad 0x3b 0x4a 0xce 0x5a 0x58 0xa4 0x3f
rxed att command: read type rsp; conn=0 length=21
D NimBLERemoteService: "Characteristic Discovered >> status: 0 handle: 1041"
txed att command: read type req; conn=0 start_handle=0x0411 end_handle=0x0430
host tx hci data; handle=0 length=11
ble_hs_hci_acl_tx(): 0x00 0x00 0x0b 0x00 0x07 0x00 0x04 0x00 0x08 0x11 0x04 0x30 0x04 0x03 0x28
21:46:47 SL1-29 got service
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=27 data=0x17 0x00 0x04 0x00 0x09 0x15 0x20 0x04 0x1a 0x21 0x04 0x2a 0xeb 0xe0 0xf4 0x90 0x6c 0x41 0xaf 0x96 0x09 0x29 0xcd 0x4d 0x43 0xe8 0xd0
rxed att command: read type rsp; conn=0 length=21
txed att command: read type req; conn=0 start_handle=0x0421 end_handle=0x0430
host tx hci data; handle=0 length=11
ble_hs_hci_acl_tx(): 0x00 0x00 0x0b 0x00 0x07 0x00 0x04 0x00 0x08 0x21 0x04 0x30 0x04 0x03 0x28
Number of Completed Packets: num_handles=1
handle:0 pkts:1
ble_hs_hci_evt_acl_process(): conn_handle=0 pb=2 len=9 data=0x05 0x00 0x04 0x00 0x01 0x08 0x21 0x04 0x0a
rxed att command: error rsp; conn=0 req_op=8 handle=0x0421 error_code=10
D NimBLERemoteService: "Characteristic Discovered >> status: 14 handle: -1"
D NimBLERemoteService: "<< Characteristic Discovered"
D NimBLERemoteService: "<< retrieveCharacteristics()"
D NimBLERemoteCharacteristic: ">> writeValue(), length: 1"
GATT procedure initiated: write; att_handle=1041 len=1
txed att command: write req; conn=0 handle=0x0411
host tx hci data; handle=0 length=8
ble_hs_hci_acl_tx(): 0x00 0x00 0x08 0x00 0x04 0x00 0x04 0x00 0x12 0x21:46:47 SL1-29 got read/write characteristic
11 0x04 0x03
[V][WebServer.cpp:291] handleClient(): New client
[V][Parsing.cpp:113] _parseRequest(): method: GET url: /cs search: c2=160
[V][Parsing.cpp:219] _parseRequest(): headerName: Host
[V][Parsing.cpp:220] _parseRequest(): headerValue: <IP_ADDRESS>

ok, found one thing.
You can deleteClient(), and then the disconnect can come in after - my fault for adding 'force' I guess....  when it comes in after the client is gone (which seems to be immediate?), the system crashes because the is not accessible any more.
but why does deleting the client enable the client event to come in? (immediately)?::
 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: "Notification characteristic not found"
D NimBLEClient: ">> disconnect()"
GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19
ble_hs_hci_cmd_send: ogf=0x01 ocf=0x0006 len=3
0x06 0x04 0x03 0x00 0x00 0x13
Command Status: status=0 cmd_pkts=5 ocf=0x6 ogf=0x1
D NimBLEClient: "ble_gap_terminate success: rc=0 "
D NimBLEClient: "<< disconnect()"
22:12:06 SL2-28 operation complete
22:12:06 SL1-29 runTaskDoneOperation: disconnecting connected client
[V][Parsing.cpp:113] _parseRequest(): method: GET url: / search: m=1
......
[V][Parsing.cpp:231] _parseRequest():  Arguments: m=1
22:12:07 SL1-29 ############################################# wait disconnect 1
22:12:08 SL1-29 ############################################# wait disconnect 2
D NimBLEClient: ">> deleteServices"
D NimBLERemoteService: ">> deleteCharacteristics"
D NimBLERemoteCharacteristic: ">> deleteDescriptors"
D NimBLERemoteCharacteristic: "<< deleteDescriptors"
D NimBLERemoteService: "<< deleteCharacteristics"
D NimBLEClient: "<< deleteServices"
D NimBLEClient: "Got Client event "
I NimBLEClient: "disconnect; reason=0, "
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

deleteClient() will disconnect the client before deleting the client instance.
Please try using the master branch with the connection parameter changes in your app you did previously. In your disconnect loop do not use isConnected() as that is set before the app callback and before the event returns to the stack. I suggest using a local variable that is set in the app callback to check for connection/disconnection and loop on that.

I've added more logging, including logging of host_rcv_pkt() in src\esp-hci\src\esp_nimble_hci.c
The run this morning ran for 1 hour before failing, but then failed twice more in 20 minutes.  Failures may have changed due to enviromental factors (wife on running machine -> electrical noise)
The failure is absolutely clearly that the disconnect packet does not arrive from the low level drivers:
bad disconnect:
GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19
ble_hs_hci_cmd_send: ogf=0x01 ocf=0x0006 len=3
0x06 0x04 0x03 0x00 0x00 0x13
D (4947685) NimBLE: >> host_rcv_pkt type:4 cmd:15
ble_hs_hci_rx_evt type:15 enqueue 0:
D (4947690) NimBLE: << host_rcv_pkt type:4 cmd:15
Command Status: status=0 cmd_pkts=5 ocf=0x6 ogf=0x1
D NimBLEClient: "ble_gap_terminate success: rc=0 SUCCESS"
D NimBLEClient: "<< disconnect()"
(nothing more from BLE for > 7s - at which time I force a restart);

Normal disconnect:
GAP procedure initiated: terminate connection; conn_handle=0 hci_reason=19
ble_hs_hci_cmd_send: ogf=0x01 ocf=0x0006 len=3
0x06 0x04 0x03 0x00 0x00 0x13
D (4916034) NimBLE: >> host_rcv_pkt type:4 cmd:15
ble_hs_hci_rx_evt type:15 enqueue 0:
D (4916039) NimBLE: << host_rcv_pkt type:4 cmd:15
Command Status: status=0 cmd_pkts=5 ocf=0x6 ogf=0x1
**D (4916044) NimBLE: >> host_rcv_pkt type:4 cmd:5**
ble_hs_hci_rx_evt type:5 enqueue 1:
**D (4916055) NimBLE: << host_rcv_pkt type:4 cmd:5**
D NimBLEClient: "ble_gap_terminate success: rc=0 SUCCESS"
D NimBLEClient: "<< disconnect()"
Disconnection Complete: status=0 handle=0 reason=22
D NimBLEClient: "Got Client event BLE_GAP_EVENT_DISCONNECT"
I NimBLEClient: "disconnect; reason=534, Connection Terminated By Local Host"

I'm going to increase the amount of time I wait for the packet to 2 minutes, to see if nimble has a long timeout somewhere.
I think we can assume that because we got "host_rcv_pkt type:4 cmd:15" that the disconnect command got sent.
The fact we never see "D (4916044) NimBLE: >> host_rcv_pkt type:4 cmd:5" I believe means this never hits us at all - I can't think that the low level is stuck somehow such that host_rcv_pkt cannot be called, but I could be wrong.

Hi @btsimonh, sorry for your troubles. I've been looking into this as well and as you pointed out in your logs the event host_rcv_pkt type:4 cmd:5 is missing.
This event is: Disconnection Complete event

The HCI_Disconnection_Complete event occurs when a connection is terminated. The status parameter indicates if the disconnection was successful or not. The reason parameter indicates the reason for the disconnection if the disconnection was successful. If the disconnection was not successful, the value of the reason parameter shall be ignored by the Host. For example, this can be the case if the Host has issued the HCI_Disconnect command and there was a parameter error, or the command was not presently allowed, or a Connection_Handle that didn’t correspond to a connection was given.

This is almost certainly an issue in the controller as it acknowledged the command but did not complete it and trigger the event.
Unfortunately the correct fix is to use a more recent IDF version with an updated controller. I don't think your PR will be merged there as the issue you are targeting only applies to the ESP32, NimBLE has their own controller for the devices they support and will not have this problem.

hmmm.. would that have been in the latest framework?  i.e.
platformio/framework-arduinoespressif32 @ https://github.com/espressif/arduino-esp32.git
I thought the
D (177683) NimBLE: >> host_rcv_pkt type:4 cmd:5
was actually a packet from the BLE device itself acknowledging disconnect? - i.e. not from the controller....

no, looks like they are stuck in January.
But I can add the new binary and test.

That event comes either when the device acknowledges the command or after the supervision timeout that you specified in the connection parameters.

hmmm.. about to scream.  IDF V4.0 would have it, and arduino-esp32.git has a #idf-release/v4.0.  But Tasmota won't have that :( - so can't easily test.  And the binary alone also does not 'fit'.
I don't suppose you fancy 'shimming' the controller until we can use a fixed version! ??? :)  esp_nimble_hci.c is ours, right?  So we can intercept all send traffic, not disconnect request, and timeout there?

hmm..  actually, it's quite a serious issue, and I can't really wait for the next official accepted esp32 release...  so 'fixing' it in esp_nimble_hci.c and making it depend on IDF version is probably a very good option for everyone.
Yep, my environment may be a bit crap; but aren't all BLE environments a bit crap.  every watch and phone and toaster now does something in the spectrum, and add the fact it's shared with wifi, we have to cope with failures. (my BLE fails to connect at 1m range ~10% of the time...  and that failure can be anywhere in the sequence.).
Please let me know if you want me to look at this, or if you would rather grip it.

Like I mentioned earlier I still think the primary cause of the trouble is using WiFi at the same time and probably triggering the controller bug.
I have not witnessed or had reports of this issue until now. In my personal projects using mqtt and BLE I just do the BLE stuff, stop and send the WiFi data after and have no such issues. Though I do not use tasmota for this.
Unless the problem becomes widespread I would prefer not to alter the stack code as it will make maintenance difficult.
Maybe @Staars has some thoughts or experience with this in tasmota?

the Tasmota code currently really only listens to advertisments...  Connection to a sensor is ONLY for battery read, and recommended once per day :(.  So @Staars will have never seen the issue, or if aware avoided it.
OK. this is how I will play it.  I have a working version.  I'll publish that as a personal Tasmota branch for me to use.
I will make the Tasmota PR as good as it can be with the existing IDF with heavy warnings attached.  It's a big addition to Tasmota, enabling generic BLE control, and simpler specific BLE drivers.
I'll ask you for some minor, heavily tested changes.  give me a few days....

just had a hang in scan->start(20):
D NimBLEScan: ">> start(duration=20)"
GAP procedure initiated: discovery; own_addr_type=0 filter_policy=0 passive=0 limited=0 filter_duplicates=0 duration=20000ms
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000b len=7
0x0b 0x20 0x07 0x01 0x70 0x00 0x50 0x00 0x00 0x00
Command complete: cmd_pkts=5 ogf=0x8 ocf=0xb status=0
ble_hs_hci_cmd_send: ogf=0x08 ocf=0x000c len=2
0x0c 0x20 0x02 0x01 0x00

and then nothing more for >120s (at which time I restarted the ESP)... so I think the issue goes deeper than just disconnect, and I don't think BLE is viable on ESP with IDF3.3
If I wanted to test what I'm doing in a low-network env with latest IDF, what project would you point me at?
I can't make Tasmota accept IDF4.2 easily - too many differences.

I just had another look at your code and I wonder if this could be caused due to the task priority of your BLE task. Just a thought but if the task priority is 0 as you have it then it's possible other tasks of higher priority are blocking your task from running for some reason. Maybe bump that up to 10 or so and check.
As for alternatives for your project, what do you want it to do? Are you just getting BLE data and sending it over MQTT? There are simpler ways to do this.

"As for alternatives for your project," - was just thinking about a better test env - one which we could both use and so agree on code and results.
I just had a 5 hour run.  One ESP reset because of the scan hangup,
More than 50 times I reset BLE because it did not disconnect.  I found that when it does not disconnect, it leaves the connection open, so decided to just reset BLE instead in this case :).
I really want this to work in Tasmota, but there is little chance of getting a late IDF into Tasmota any time soon.
SO.  Latest approach is back to square one.  Now we know the effects of the faults in the underlying systems, I'm just going to look for them, and cover them up through BLE restarts and ESP restarts.  It's the best and probably the only way to deal with it for the moment.
I will be proposing some very minor, low impact changes for NimBLE-arduino.
I need the connect() low level return code, so have added m_result and getResult() (called if connect() fails - e.g. through lack of resource - as else we have no idea the system is broken).
And I moved m_waitingToConnect = true; to before the call to the low level, as I definitely saw this set to false by the callback BEFORE being set to true after asking BLE to connect. (maybe because I changed the vTaskDelay value to 1 rather than 1/portTICK_PERIOD_MS => 0, which I still would recommend but not insist on).
To 'fix' a disconnection timeout (after 5s), I am calling
          int conn_id = (*ppClient)->getConnId();
          ble_gap_conn_broken(conn_id, -1);

This seems to give you the disconnect callback, and things continue normally after that...
Up to you if you consider something similar within NimBLE-arduino, or doing anything with unrecoverable connect() failure.
(I have just started a run based on current Tasmota development branch including NimBLE-arduino 1.0.2 (with their & my minor mods, IDF3.3 from framework-arduinoespressif32 @ https://github.com/tasmota/arduino-esp32/releases/download/<IP_ADDRESS>/esp32-<IP_ADDRESS>.zip, and it's looking good after 30 mins.  multiple fails, but all recovered.)
thanks again for all your attention so far,
br,  simon.
p.s. just got a esp32-cam module with external +8db antenna.  Gives me 20dB extra on BLE compared to my 'normal' dev module.  With careful location, I may be able to cover the house with just two modules - just wish esp32 with external antenna were easier to find!

pls check branch
https://github.com/btsimonh/NimBLE-Arduino/tree/1.0.2-btsimonh
for the specific changes I would really like :).  Very minor, and no impact on others....

I deal with connect failure here:
https://github.com/btsimonh/Tasmota/blob/2c34353b72c3f371bb5d7d2f31c267820e3601b3/tasmota/xdrv_47_BLE_ESP32.ino#L1722
I'm not sure whether it's strictly necessary with my new approach explained above, but there are certain failures which cannot be recovered from without special attention - the two mentioned were observed.

I need the connect() low level return code, so have added m_result and getResult() (called if connect() fails - e.g. through lack of resource - as else we have no idea the system is broken).

While I can see this being useful for you right now, it's indicating to me that something else is going on. Considering this:

I moved m_waitingToConnect = true; to before the call to the low level, as I definitely saw this set to false by the callback BEFORE being set to true after asking BLE to connect.

That is nearly impossible unless a previous disconnect call just returned in the callback at the same time as you are calling connect. Also looking at the return codes you're testing for, that seems to be exactly what is happening.

(maybe because I changed the vTaskDelay value to 1 rather than 1/portTICK_PERIOD_MS => 0, which I still would recommend but not insist on).

The change for vTaskDelay is an issue as arduino uses 1000hz tick rate so 1/portTICK_PERIOD_MS is the correct parameter to use. The issue as brought up in arduino-esp32 only relates to using arduino as an IDF component where the default is 100hz tick rate.
I'm curious about the timing of the events that trigger your issues. I know I can force the failure by simply sending too many commands to the controller in a short period of time (command stack is only 1) and if done from multiple tasks it will hang. I have tested this and it is also why I modified the esp-nimble code to send commands only from tasks on core 0 to prevent such occurrences.

"That is nearly impossible unless a previous disconnect call just returned" -
no, you set the m_waitingToConnect=true AFTER calling into the low level.
The low level calls you back, and in your callback, you set it to false..
If it manages to do this BEFORE you hit your set to true, then the setting it to true AFTER it has been set to false will remain true forever.....
"nearly impossible" - but I observed it.  150Mbytes of logging.  Three weeks of work.  It happened twice.  The mod is harmless if it's not the case, but if it is the case, then it solves an instability.  Personally, I am pleased to have observed it :).
vTaskDelay - I defer to you.  so 1/portTICK_PERIOD_MS == 1.  why not use 1 as a minimum delay?  but i don't care :)
"something else is going on" - yes.  The low level sometimes (rarely) does not respond correctly. (150 Mbytes of logging, etc., etc.). We hope it would be fixed in the IDF.  But can we leave those who are still on 3.3 hanging with BLE which is compromised?
Latest run:
~23 disconnect timeouts corrected using the code I highlighted in 2 1/2 hours.  About 1 connection/disconnection attempted every 5-10 seconds.  About 1/3 or connections or more to devices on verge of range, and so failing with a variety of failures.  No reboots so far.  Looking very good considering.  Expecting reboots triggered by scan hang (nothing we can do about that?) - unless all the diags affected it. (but if it CAN happen with diags on, it CAN happen without?).

no, you set the m_waitingToConnect=true AFTER calling into the low level.
The low level calls you back, and in your callback, you set it to false..

Actually, the stack returns as soon as the command is sent to the controller(non-blocking). By the time we set the flag the controller hasn't even started the receiver. That is set after for a reason (incase of failure, we aren't waiting for a connection if the command failed). I have been using this for nearly 9 months and have not had this issue or seen in reported in all this time, However the code should be changed anyway, I just wanted to point out why I think it could be indicating something.

vTaskDelay - I defer to you. so 1/portTICK_PERIOD_MS == 1. why not use 1 as a minimum delay? but i don't care :)
The intent is to have a 1ms delay, so we don't loop too fast and stuff up the controller (it breaks easy as you can see lol). Yes we could use 1 for arduino, but this code is also used as a standalone IDF component which could have higher tick rates in config and I'd like to keep the code the same. Makes no difference here anyway :)

I'm curious if you ever see BLE_ERR_CONN_LIMIT or BLE_ERR_ACL_CONN_EXISTS in your testing. If so, do you have a log with those codes?

"the stack returns as soon as the command is sent to the controller(non-blocking)" -yep, it would have to be BLE_HS_EBUSY to loop - unless the task happened to be schedule out in the time between.  (I don't know IF the task management can swap tasks if you don't yield).
"BLE_ERR_CONN_LIMIT or BLE_ERR_ACL_CONN_EXISTS" - yes.  But before I started calling ble_gap_conn_broken.  i.e. I think my timeout within the lower stack was flawed.  However; if either of these happens at connect, it should be dealt with.  In my case, I should only ever have one connection - so either of these are bad news.  I'm not specifically monitoring the logs for these now - I'll add them and let you know if they happen.
br, simon

I don't know IF the task management can swap tasks if you don't yield).
It task switches on any call to vTaskDelay() which is why I was talking about your task priority level earlier, you delay in it and it might not get priority back for a while.

To be honest, the code you have is quite large and I don't know what tasmota is doing under the hood so I'm speculating a bit here as to where conflicts can happen. If you are getting those return codes that suggests (from what I can see) that a call is being made more than once to ::createClient() and possibly connecting to the same device twice.

no, it was the way I was timing out the connection in the layer below you (previously), I believe.  I'm pretty sure it can never have two clients or connect twice.

"21:42:23 SL2-28 Connection exists? - restarting NimBLE" - yes.  Twice in 10 minutes.
So... I'm calling ble_gap_conn_broken which lets the client continue.  But obviously does not clear the connection?

I'm pretty sure I just lost a scanended callback :(.  But more checking of my code required.

Been thinking about this and I'm almost 100% positive you are somehow connected to a device twice.

ok, found one thing.
You can deleteClient(), and then the disconnect can come in after

I have been able to reproduce this behavior exactly by creating 2 connections to a device. Doing what you have stated above will close the connection because deleteClient() calls disconnect again.

Latest results.
I have an esp32Cam with external antenna which i've left running.
Uptime since last flash is 2 1/2 days.
Total notify operations in that time 10000.
stats of reasons for restarting BLE: (including some from before the flash):
"blerestart": {
"connect failed with connection exists": 1171,
"no adverts in 120s": 3, - I think these may be from before the last flash.
"connect failed with connection limit reached": 5 - I think these may be from before the last flash.
},
Stats for operation results:
"state": {
"DONENOTIFIED": 16618,
"FAILCONNECT": 6429,
"FAILNOTIFY": 29,
"FAILNOTIFYTIMEOUT": 1158,
"FAILNONOTIFYCHAR": 323,
"FAILNOSERVICE": 134
},
it can currently see:
mac	name	RSSI
001A22092C9A	CC-RT-M-BLE	-77
001A22092FB7	CC-RT-M-BLE	-82
001A22092CDB	CC-RT-M-BLE	-58
4C65A8DAF43A	MJ_HT_V1	-65
001A22085B1E	CC-RT-M-BLE	-88
2A958C399F5B		-56
0750408D5F2C		-62
(the CC-RT-M-BLE are the ones it's connecting to, one at a time, with 15s between operations).
Q: would it report connection exists if the DEVICE had an existing connection?  I cannot rule out two ESPs both trying to connect at the same time...
I'm fairly pleased with the stability now, with what I have done on the outside to mitigate 'bad' things.
It would be nice if the code dealt with or gave the ability to deal with these inside.
Memory seems quite stable.

Q: would it report connection exists if the DEVICE had an existing connection? I cannot rule out two ESPs both trying to connect at the same time...

The controller returns that code if it is still synced with the device you're trying to connect to. If 2 clients are connecting at the same time the device should allow both if capable or just the first one it received the request from and the other would hang until timeout.
For a test that may have interesting results what you can do is call pClient->disconnect() 2 or more times, maybe with a 50ms delay between each call, and see what happens. Worst case you'll get a few error messages with rc=2.

"I'm almost 100% positive you are somehow connected to a device twice" - -> I'm almost 100% positive that I ditch a connection whilst active, and something remembers that :).
"call pClient->disconnect() 2 or more times" -> disconnect aborts immediately without sending anything to the controller as pClient believes itself connected :(.

Here is something interesting regarding this:  https://esp32.com/viewtopic.php?t=4625.

yes, interesting.
I believe I did find an issue with my code where I could re-start scanning before the scan complete callback had finished.  This could be a bad thing, so will keep an eye on performance now that is resolved (now I have the scancomplete event set BLERunningScan = 2 to indicate it's over (rather than 0), and detect that elsewhere, wait 100ms, then allow it to start the scan next loop (1s away).
could it be that that if you call ->start() from outside of the complete callback, bur DURING the complete callback, that the scan class could start another scan and then forget that it did?  - I found this because I was getting multiple complete callbacks (up to 3 at one point!) when I stopped a scan.
br, simon

Interesting, I guess it could be possible if using the blocking scan and manually stopping/starting it from a task on another core. I'll have to look at this.

non-blocking in my case.  MUCH more stable now.  I'll see if I can setup another long-running run this evening (i.e. connect one device to a PSU rather than the PC, and leave it running, logging via MQTT the number of restarts, etc.  not seen any in the few minutes that I could monitor manually.)

Good that you've found a way to improve this. I was doing some testing and actually stumbled into a similar fault on disconnect. In my case it eventually disconnected but it was nearly 10 minutes after. Sadly it has not happened since so I cannot trace this yet, I will continue to try reproducing.

It seems I may have stumbled onto something with this. I have a server device placed in a noisy area that is configured to send indications not notifications and upon calling disconnect I occasionally get this delay/hang. Just speculating here but after receiving the indication the client sends an ACK to the server on the next connection interval, if we call disconnect before that happens it may trigger this issue. This could also happen with notifications as they are ACK'd but at the link layer.
So my theory on this is that the controller is waiting for the connection interval event to send and ACK and if we tell it to disconnect before that happens it ignores the command. I will continue testing with my setup as I can now get it to happen every 15 mins or so.

Results of testing by round robin connecting to 3 devices at long range/poor connections while monitoring output over telnet(wifi):
Connection settings: pClient->setConnParams(6,6,0,250); (2500ms supervision timeout).

Calling disconnect occasionally hangs (no callback received) if starting a scan operation before the callback comes.

Calling disconnect and then delaying for 2000ms before starting a scan operation, hangs much less often.

Calling disconnect and then delaying for 2500ms (supervision timeout) does not hang at all.

This is using espressif/arduino-esp32 675a40b and NimBLE-Arduino 5265292 .

good news.  One thing of note; in my earlier testing, I was writing but not subscribing for notification - BUT - at the low level the notifications still arrived (just ignored by lower level NimBLE) - I'm guessing that my devices send the notification packet even if not specifically asked for (if this is how BLE works?).
Silly unrelated questions:
1/ can a device be both a 'central' scanning and connecting to devices, and send advertisments - i.e. can I make the Tasmota look like an iBeacon with a txpower, name, and rssi whilst still being able to control other devices?
2/ is there any advantage to pinning to core 1?
3/ Does CPU freq have any effect on BLE (seems we were running 80mhz by default.  Have reconfigured for 240 now, and it still seems to work....)

One thing of note; in my earlier testing, I was writing but not subscribing for notification - BUT - at the low level the notifications still arrived (just ignored by lower level NimBLE) - I'm guessing that my devices send the notification packet even if not specifically asked for (if this is how BLE works?).

There are some devices out there that do this, I think those LWYS... devices do. It's allowed by spec as I recently discovered, don't know why they would do this if nobody is listening but they do.
1 - Yes, if you adjust the intervals so there is enough time to do this you can.
2 - Pinning to core 1 puts less tasks on the BLE and WiFi core so it has more time to do low level stuff. If your tasks are short though, core 0 is fine.
3 - I always run at 240mhz, especially when using BLE and WiFi. I don't see a reason to run slower unless running off a battery.

@btsimonh I have created a new branch to address some of the things in this thread. Would you be able to test it and let me know if it helps?
https://github.com/h2zero/NimBLE-Arduino/tree/client-bugfix
@tonton81 Could you bring your disconnect / connect hang discussion here? Also please test the new branch if you could.

yes, the symptom of the OP is the same as me (except i dont use notify at all in this setup)
it can be replicated by calling a disconnect every 5 seconds in the loop and when the scanner picks up the device it reconnects... eventually.. disconnecting stops working and/or one of 2 clients dont disconnect but other does, eventually leading to a stall when it reaches connect() method Take call

I have hacked up a way to reproduce this, initial testing shows that the controller stops sending events.
The cause appears to be due to exceeding the maximum number of connections, which likely overflows a buffer in the controller.
This can happen if disconnect is called and the connect is called before the disconnection event is sent. This can also happen even when the client instance is deleted if the delete call fails and is not checked before creating a new instance and connecting again.
This is just my initial assessment, I will continue to verify this and create a patch for it shortly.

@tonton81 @btsimonh
After testing for the day I think the latest commit at https://github.com/h2zero/NimBLE-Arduino/tree/client-bugfix will resolve both of your issues. Please test when you can and let me know the results. I hope to merge this soon.

Just loaded it, gonna let it run on a 5sec interval disconnect. I'll report back if it crashes. If it's good I can give it a better test later on, I received a 3rd XBT module, could easily do 3 connections/disconnections per 5 mins :)

Currently it just stopped disconnecting one client but still disconnect/reconnecting the other

E NimBLEClient: "ble_gap_terminate failed: rc=2 "
D NimBLEClient: "<< disconnect()"
D NimBLEClient: ">> disconnect()"
D NimBLEClient: "<< disconnect()"
D NimBLEClient: ">> disconnect()"
D NimBLEClient: "<< disconnect()"
D NimBLEClient: ">> disconnect()"
D NimBLEClient: "Got Client event "
D NimBLEClient: "<< disconnect()"
I NimBLEClient: "disconnect; reason=534, "
Ok so 1 is disconnecting the other gets an error

Check this:
{
NimBLEScan: "UPDATING PREVIOUSLY FOUND DEVICE: 48:58:b4:2a:2c:42"
D NimBLEAdvertisedDevice: "payload: 1eff060001092002d807bbdbab0c6653577da2cae3109cc99739c052294d95"
I NimBLEScan: "UPDATING PREVIOUSLY FOUND DEVICE: 48:58:b4:2a:2c:42"
D NimBLEAdvertisedDevice: "payload: 1eff060001092002d807bbdbab0c6653577da2cae3109cc99739c052294d95"
D NimBLEScan: "discovery complete; reason=0"
RGB Light was found.
D NimBLEClient: ">> connect(f0:b5:d1:8f:b6:b8)"
W NimBLEClient: "Already connected to this device; addr=f0:b5:d1:8f:b6:b8"
D NimBLEClient: ">> getService: uuid: 0xffd0"
D NimBLEUUID: "Comparing UUIDs; type 128 to 16; UUID 0000ffd0-0000-1000-8000-00805f9b34fb to 0xffd0"
D NimBLEClient: "<< getService: found the service with uuid: 0xffd0"
D NimBLERemoteService: ">> getCharacteristic: uuid: 0xffd1"
D NimBLEUUID: "Comparing UUIDs; type 128 to 16; UUID 0000ffd1-0000-1000-8000-00805f9b34fb to 0xffd1"
D NimBLERemoteService: "<< getCharacteristic: found the characteristic with uuid: 0xffd1"
D NimBLERemoteCharacteristic: ">> readValue(): uuid: 0000ffd1-0000-1000-8000-00805f9b34fb, handle: 37 0x25"
E NimBLERemoteCharacteristic: "Disconnected"
XBT controller was repowered, setting all channels off...
}
looks like the characteristic dropped to disconnected on the one that doesn't connect and reports all 00's for data which tells my code that it's a XBT reset when it's not.

D NimBLEScan: "discovery complete; reason=0"
RGB Light was found.
D NimBLEClient: ">> connect(f0:b5:d1:8f:b6:b8)"
W NimBLEClient: "Already connected to this device; addr=f0:b5:d1:8f:b6:b8"
D NimBLEClient: ">> getService: uuid: 0xffd0"

Some things to note from this:
I'm guessing you are scanning with the isContinue flag set to true? If so you are getting the old results of the scan and new ones. I say this because a client instance is already connected to that device (4th line) and it should be ignored by the scan or shouldn't be advertising unless it's capable of multiple connections.
The read is failing because the client did not connect. What happened here was the call to ::connect() returned false after the warning "Already connected to this device;" and after that a call was made to getService() even though connect failed. This will work because the cached services and characteristics instances are still available but the call to readValue() fails because the connection failed.
Solution: check the return value of the ::connect() call before retrieving data from the device.
If the read fails for any reason it will return a NULL string, this is a limitation of the library returning the value instead of a success/fail indication. I would like to change that but it would break a lot of user apps, something to ponder in the future.
What you can do however is use a timestamp as a flag, something like this:
time_t t = 0;
value = readValue(&t);
if(value = 0) {
    if(t = 0) {
        "disconnected"
    } else {
        "XBT reset"
    }
} else {
    "value read: value"
}

Now for the "Already connected to this device;" issue. This is what I have added in the bugfix branch, it is there to prevent having multiple connections to the same device, which in turn prevents the hanging on disconnection. Unfortunately BLE is very slow, in the specifications when we want to disconnect we must either wait for the peripheral to acknowledge it or wait for the supervision timeout before the connection is considered broken. This can take anywhere from 1 connection interval time to 32 seconds depending on connection settings. So if you were connected to a device with lets say a 10 second supervision timeout and called disconnect but the device doesn't respond for some reason (reset or whatever) then you will still be considered connected by the stack for up to that 10 second timeout.
So in this case it looks that one of your client instances has not yet disconnected from that peripheral and attempting to connect to it again with a different client instance returned with a failure since you're still connected as far as the stack is concerned.

the clients are static global, not dynamically allocated, so they are re-used for theur own specific MAC address client. i am not using isContinue but rather the asybc callback setting a volatile flag so the loop() will connect after, but i'll checkout the connect and readvalue returns

the clients are static global, not dynamically allocated, so they are re-used for theur own specific MAC address client.

OK, in that case I would have expected the other message on the connect failure; "Client connected to %s, must disconnect first"
but that might not have happened due to the change you added earlier. Doesn't matter anyway, result is the same.

i am not using isContinue but rather the async scan callback setting a volatile flag so the loop() will connect after

That makes sense if the callback sets the flag when any device with the addresses you want is found, explains the log, thanks.

@h2zero - I have updated NimBLE to the master branch.
Also using "Core":"1_0_5_RC4","SDK":"v3.3.4-286-gb4c075169"
Do you want me to include your additional changes (2 other branches...)?
I have 12 hours of stats from a run with the base Tasmota NimBLE version, and will  now restart that with the newer version. and report.
I added my m_result and getResult() in client so I did not have to change any of my code.

@h2zero - I have updated NimBLE to the master branch.
Also using "Core":"1_0_5_RC4","SDK":"v3.3.4-286-gb4c075169"
Do you want me to include your additional changes (2 other branches...)?
I have 12 hours of stats from a run with the base Tasmota NimBLE version, and will  now restart that with the newer version. and report.
I added my m_result and getResult() in client so I did not have to change any of my code.

initial results; no change.
Note that I detect the '523' response (0x0200+BLE_ERR_ACL_CONN_EXISTS) from ble_gap_connect and restart NimBLE if I see this (easy way out).
Note it happens after a disconnect timeout.
At disconnect timeout, I am calling
          int conn_id = (*ppClient)->getConnId();
          ble_gap_conn_broken(conn_id, -1);

to allow the client to carry on, but it just delays the inevitable restart.
Aside: I really struggle with the affect on TCP by BLE scanning.  No combination of  Interval and Window improves it.
The TCP WORKS, it's just terribly slow (maybe it gets broken at low levels, and TCP timeouts 'repair' it?
Think I'm using software sharing, but not yet latest IDF, so I guess i just cope for now, unless you have thoughts.
my logs attached: (will look at enabling NimBLE and SDK logs if you think this would be helpful?  - just remind me what to set....)
11:52:38.312 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:522843 go"
11:52:38.347 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":1,"u":522843}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)**
11:52:41.435 failed to connect to device 0
11:52:41.539 BLETask: op failed -11
11:52:41.887 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"1","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"522843","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:52:42.021 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:901578 go"
11:52:42.031 SRC: MQTT
11:52:42.033 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:901578 go"
11:52:42.071 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":2,"u":901578}}
11:52:47.667 WIF: Checking connection...
11:52:52.876 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"2","stat":"7","state":"DONENOTIFIED","MAC":"001A22092C9A","u":"901578","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"0201093B042E"}}
11:52:52.959 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:720702 go"
11:52:52.968 SRC: MQTT
11:52:52.971 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:720702 go"
11:52:53.001 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":3,"u":720702}}
11:52:54.868 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"3","stat":"7","state":"DONENOTIFIED","MAC":"001A22092CDB","u":"720702","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"02010800042A"}}
11:52:54.952 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:371068 go"
11:52:54.962 SRC: MQTT
11:52:54.964 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:371068 go"
11:52:54.995 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":4,"u":371068}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:52:55.373 failed to connect to device 0**
11:52:55.478 BLETask: op failed -11
11:52:55.863 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"4","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"371068","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:52:55.947 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:963245 go"
11:52:55.955 SRC: MQTT
11:52:55.958 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:963245 go"
11:52:55.988 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":5,"u":963245}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:52:58.523 failed to connect to device 0**
11:52:58.626 BLETask: op failed -11
11:52:58.886 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"5","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"963245","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:52:59.032 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:998396 go"
11:52:59.042 SRC: MQTT
11:52:59.044 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:998396 go"
11:52:59.075 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":6,"u":998396}}
**11:53:06.707 BLE wait discon1
11:53:07.668 WIF: Checking connection...
11:53:07.711 BLE wait discon2
11:53:08.714 BLE wait discon3
11:53:09.719 BLE wait discon4
11:53:10.221 BLE wait discon5 - kill connection**
11:53:10.901 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"6","stat":"7","state":"DONENOTIFIED","MAC":"001A22092C9A","u":"998396","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"0201093B042E"}}
11:53:11.041 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:639792 go"
11:53:11.050 SRC: MQTT
11:53:11.053 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:639792 go"
11:53:11.085 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":7,"u":639792}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:11.556 failed to connect to device 0**
11:53:11.657 BLETask: op failed -11
11:53:11.888 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"7","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"639792","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:12.084 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:681943 go"
11:53:12.093 SRC: MQTT
11:53:12.095 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:681943 go"
11:53:12.127 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":8,"u":681943}}
**11:53:12.137 Connection exists? - restarting NimB
11:53:12.140 failed to connect to device 523
11:53:12.242 BLETask: Restart NimBLE - restart Ta
11:53:12.244 BLETask:Stopping NimBLE
11:53:12.248 deleted client
11:53:12.363 BLETask:Starting NimBLE
11:53:12.931 MQT: tele/tasmota_esp32/BLE = {"blerestart":"connect failed with connection exists"}
11:53:12.933 BLE Failure! Restarting BLE Stack because connect failed with connection exists**
11:53:12.950 BLETask: op failed -11
11:53:13.894 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"8","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"681943","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:14.029 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:548986 go"
11:53:14.038 SRC: MQTT
11:53:14.040 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:548986 go"
11:53:14.074 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":9,"u":548986}}
11:53:17.908 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"9","stat":"7","state":"DONENOTIFIED","MAC":"001A22092CDB","u":"548986","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"02010800042A"}}
11:53:18.043 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:732808 go"
11:53:18.053 SRC: MQTT
11:53:18.054 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:732808 go"
11:53:18.088 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":10,"u":732808}}
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:24.918 failed to connect to device 0
11:53:25.022 BLETask: op failed -11
11:53:25.910 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"10","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"732808","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:26.065 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:748401 go"
11:53:26.074 SRC: MQTT
11:53:26.077 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:748401 go"
11:53:26.102 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":11,"u":748401}}
11:53:27.696 WIF: Checking connection...
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:29.043 failed to connect to device 0
11:53:29.148 BLETask: op failed -11
11:53:29.869 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"11","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"748401","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:29.951 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:716145 go"
11:53:29.960 SRC: MQTT
11:53:29.962 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:716145 go"
11:53:29.995 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":12,"u":716145}}
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:33.936 failed to connect to device 0
11:53:34.038 BLETask: op failed -11
11:53:34.870 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"12","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"716145","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:35.007 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:762292 go"
11:53:35.017 SRC: MQTT
11:53:35.019 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:762292 go"
11:53:35.057 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":13,"u":762292}}
11:53:38.875 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"13","stat":"7","state":"DONENOTIFIED","MAC":"001A22092CDB","u":"762292","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"02010800042A"}}
11:53:38.960 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A

initial results; no change.
Note that I detect the '523' response (0x0200+BLE_ERR_ACL_CONN_EXISTS) from ble_gap_connect and restart NimBLE if I see this (easy way out).
Note it happens after a disconnect timeout.
At disconnect timeout, I am calling
          int conn_id = (*ppClient)->getConnId();
          ble_gap_conn_broken(conn_id, -1);

to allow the client to carry on, but it just delays the inevitable restart.
Aside: I really struggle with the affect on TCP by BLE scanning.  No combination of  Interval and Window improves it.
The TCP WORKS, it's just terribly slow (maybe it gets broken at low levels, and TCP timeouts 'repair' it?
Think I'm using software sharing, but not yet latest IDF, so I guess i just cope for now, unless you have thoughts.
my logs attached: (will look at enabling NimBLE and SDK logs if you think this would be helpful?  - just remind me what to set....)
11:52:38.312 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:522843 go"
11:52:38.347 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":1,"u":522843}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)**
11:52:41.435 failed to connect to device 0
11:52:41.539 BLETask: op failed -11
11:52:41.887 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"1","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"522843","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:52:42.021 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:901578 go"
11:52:42.031 SRC: MQTT
11:52:42.033 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:901578 go"
11:52:42.071 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":2,"u":901578}}
11:52:47.667 WIF: Checking connection...
11:52:52.876 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"2","stat":"7","state":"DONENOTIFIED","MAC":"001A22092C9A","u":"901578","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"0201093B042E"}}
11:52:52.959 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:720702 go"
11:52:52.968 SRC: MQTT
11:52:52.971 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:720702 go"
11:52:53.001 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":3,"u":720702}}
11:52:54.868 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"3","stat":"7","state":"DONENOTIFIED","MAC":"001A22092CDB","u":"720702","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"02010800042A"}}
11:52:54.952 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:371068 go"
11:52:54.962 SRC: MQTT
11:52:54.964 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:371068 go"
11:52:54.995 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":4,"u":371068}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:52:55.373 failed to connect to device 0**
11:52:55.478 BLETask: op failed -11
11:52:55.863 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"4","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"371068","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:52:55.947 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:963245 go"
11:52:55.955 SRC: MQTT
11:52:55.958 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:963245 go"
11:52:55.988 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":5,"u":963245}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:52:58.523 failed to connect to device 0**
11:52:58.626 BLETask: op failed -11
11:52:58.886 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"5","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"963245","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:52:59.032 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:998396 go"
11:52:59.042 SRC: MQTT
11:52:59.044 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:998396 go"
11:52:59.075 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":6,"u":998396}}
**11:53:06.707 BLE wait discon1
11:53:07.668 WIF: Checking connection...
11:53:07.711 BLE wait discon2
11:53:08.714 BLE wait discon3
11:53:09.719 BLE wait discon4
11:53:10.221 BLE wait discon5 - kill connection**
11:53:10.901 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"6","stat":"7","state":"DONENOTIFIED","MAC":"001A22092C9A","u":"998396","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"0201093B042E"}}
11:53:11.041 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:639792 go"
11:53:11.050 SRC: MQTT
11:53:11.053 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:639792 go"
11:53:11.085 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":7,"u":639792}}
**lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:11.556 failed to connect to device 0**
11:53:11.657 BLETask: op failed -11
11:53:11.888 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"7","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"639792","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:12.084 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:681943 go"
11:53:12.093 SRC: MQTT
11:53:12.095 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:681943 go"
11:53:12.127 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":8,"u":681943}}
**11:53:12.137 Connection exists? - restarting NimB
11:53:12.140 failed to connect to device 523
11:53:12.242 BLETask: Restart NimBLE - restart Ta
11:53:12.244 BLETask:Stopping NimBLE
11:53:12.248 deleted client
11:53:12.363 BLETask:Starting NimBLE
11:53:12.931 MQT: tele/tasmota_esp32/BLE = {"blerestart":"connect failed with connection exists"}
11:53:12.933 BLE Failure! Restarting BLE Stack because connect failed with connection exists**
11:53:12.950 BLETask: op failed -11
11:53:13.894 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"8","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"681943","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:14.029 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:548986 go"
11:53:14.038 SRC: MQTT
11:53:14.040 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:548986 go"
11:53:14.074 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":9,"u":548986}}
11:53:17.908 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"9","stat":"7","state":"DONENOTIFIED","MAC":"001A22092CDB","u":"548986","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"02010800042A"}}
11:53:18.043 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:732808 go"
11:53:18.053 SRC: MQTT
11:53:18.054 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:732808 go"
11:53:18.088 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":10,"u":732808}}
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:24.918 failed to connect to device 0
11:53:25.022 BLETask: op failed -11
11:53:25.910 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"10","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"732808","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:26.065 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:748401 go"
11:53:26.074 SRC: MQTT
11:53:26.077 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:748401 go"
11:53:26.102 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":11,"u":748401}}
11:53:27.696 WIF: Checking connection...
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:29.043 failed to connect to device 0
11:53:29.148 BLETask: op failed -11
11:53:29.869 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"11","stat":"-11","state":"FAILCONNECT","MAC":"001A22092CDB","u":"748401","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:29.951 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:716145 go"
11:53:29.960 SRC: MQTT
11:53:29.962 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092C9A s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:716145 go"
11:53:29.995 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":12,"u":716145}}
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
11:53:33.936 failed to connect to device 0
11:53:34.038 BLETask: op failed -11
11:53:34.870 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"12","stat":"-11","state":"FAILCONNECT","MAC":"001A22092C9A","u":"716145","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03"}}
11:53:35.007 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:762292 go"
11:53:35.017 SRC: MQTT
11:53:35.019 CMD: Group 0, Index 1, Command "BLEOP", Data "m:001A22092CDB s:3e135142-654f-9090-134a-a6ff5bb77046 c:3fa4585a-ce4a-3bad-db4b-b8df8179ea09 n:d0e8434d-cd29-0996-af41-6c90f4e0eb2a w:03 u:762292 go"
11:53:35.057 MQT: stat/tasmota_esp32/RESULT = {"BLEOp":{"opid":13,"u":762292}}
11:53:38.875 MQT: tele/tasmota_esp32/BLE = {"BLEOperation":{"opid":"13","stat":"7","state":"DONENOTIFIED","MAC":"001A22092CDB","u":"762292","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03","notify":"02010800042A"}}
11:53:38.960 MQT: Data Size 148, "cmnd/tasmota_esp32/BLEOp1 m:001A22092C9A

damn.. just got hang ending load prohibited from
pxPortInitialiseStack->
NimBLEClient14deleteServices->
NimBLEAddress9getNativeEv?->
RtcRebootLoadv???
I THINK it was trying to maybe reboot due to a core watchdog timeout, and when destroying the task some static class delete went wrong?

damn.. just got hang ending load prohibited from
pxPortInitialiseStack->
NimBLEClient14deleteServices->
NimBLEAddress9getNativeEv?->
RtcRebootLoadv???
I THINK it was trying to maybe reboot due to a core watchdog timeout, and when destroying the task some static class delete went wrong?

@btsimonh Thanks, could you test the client-bugfix branch without any changes and post a debug log?
Not sure about the crash there, my guess is a nullptr operations somewhere, hard to say.

@btsimonh Thanks, could you test the client-bugfix branch without any changes and post a debug log?
Not sure about the crash there, my guess is a nullptr operations somewhere, hard to say.

hmm..  seems that the new code expects to find a client which is already connected.  In my case, I only ever have one client, so it should not find it?  (i.e. the 'connected' client is the one which I ask to connect to the next device... but that does not work because the client believes itself to be connected, but can't be disconnected.)
And this sort of indicates that the connection is still valid...  if that WAS the case, then surely we should be able to disconnect it when we find a disconnect timeout? - but I'm pretty sure the low level denied that when I was looking at it.
Also, the response I see for already connected is (0x0200+BLE_ERR_ACL_CONN_EXISTS), not BLE_HS_EDONE?
Crash above happened again (just caught it in my serial log), but also in Holland.  It stalls everything for 30s (no wireless, no other task debug), then blows up.

hmm..  seems that the new code expects to find a client which is already connected.  In my case, I only ever have one client, so it should not find it?  (i.e. the 'connected' client is the one which I ask to connect to the next device... but that does not work because the client believes itself to be connected, but can't be disconnected.)
And this sort of indicates that the connection is still valid...  if that WAS the case, then surely we should be able to disconnect it when we find a disconnect timeout? - but I'm pretty sure the low level denied that when I was looking at it.
Also, the response I see for already connected is (0x0200+BLE_ERR_ACL_CONN_EXISTS), not BLE_HS_EDONE?
Crash above happened again (just caught it in my serial log), but also in Holland.  It stalls everything for 30s (no wireless, no other task debug), then blows up.

The code change is to prevent connecting (again) to a peer when a connection to it already exists. Because what happens is, when you connect and then disconnect, if the disconnect event has not come before calling connect again you will be connected twice, and now you'll have 2 connection id's to the same device. At that point you can get stuck because calling disconnect will not trigger an event since the controller is still maintaining a connection to the peer on the other connection id.

The code change is to prevent connecting (again) to a peer when a connection to it already exists. Because what happens is, when you connect and then disconnect, if the disconnect event has not come before calling connect again you will be connected twice, and now you'll have 2 connection id's to the same device. At that point you can get stuck because calling disconnect will not trigger an event since the controller is still maintaining a connection to the peer on the other connection id.

the crash is not newer nimble related.  I was reading the wrong map file!!!!

the crash is not newer nimble related.  I was reading the wrong map file!!!!

Also, the response I see for already connected is (0x0200+BLE_ERR_ACL_CONN_EXISTS), not BLE_HS_EDONE?

BLE_HS_EDONE is the NimBLE host response to the app when it checks for a connection before attempting to connect. This was not dealt with correctly before and would report success when it actually didn't create a new connection.
BLE_ERR_ACL_CONN_EXISTS is the response from the controller to NimBLE if it attempts to connect and already is, here is the definition:

2.11   CONNECTION ALREADY EXISTS (0x0B)
The Connection Already Exists error code indicates that an attempt was made to create a new Connection to a device when there is already a connection to this device and multiple connections to the same device are not permitted.

Also, the response I see for already connected is (0x0200+BLE_ERR_ACL_CONN_EXISTS), not BLE_HS_EDONE?

BLE_HS_EDONE is the NimBLE host response to the app when it checks for a connection before attempting to connect. This was not dealt with correctly before and would report success when it actually didn't create a new connection.
BLE_ERR_ACL_CONN_EXISTS is the response from the controller to NimBLE if it attempts to connect and already is, here is the definition:

2.11   CONNECTION ALREADY EXISTS (0x0B)
The Connection Already Exists error code indicates that an attempt was made to create a new Connection to a device when there is already a connection to this device and multiple connections to the same device are not permitted.

I had a crash in base level IDF BLE (coex_schm_xxx related, but also many core 0 hangs), so have reverted back to arduino esp32-<IP_ADDRESS>.zip  from "Core":"1_0_5_RC4","SDK":"v3.3.4-286-gb4c075169"- i'll report.  Back on older NimBLE still, but will try the later branch once I know I've not got crashes....

I had a crash in base level IDF BLE (coex_schm_xxx related, but also many core 0 hangs), so have reverted back to arduino esp32-<IP_ADDRESS>.zip  from "Core":"1_0_5_RC4","SDK":"v3.3.4-286-gb4c075169"- i'll report.  Back on older NimBLE still, but will try the later branch once I know I've not got crashes....

found and fixed probably the main source of my crashing today (double mutex deadlock locking up both main and BLE task).  Once proven stable, will try again with new branch & later IDF.

found and fixed probably the main source of my crashing today (double mutex deadlock locking up both main and BLE task).  Once proven stable, will try again with new branch & later IDF.

Glad to hear you fixed that, I know the mutex pain well.

Glad to hear you fixed that, I know the mutex pain well.

ok, everything is very stable now, but still with the old (&modified) version and non-disconnect -> already connected with rc code above.  Wifi/BLE sharing improved with later 1_0_5_RC4 arduino core...
Could you publish a basic test repo (preferably VSCode/Arduino), and I'll build the simplest test on top, so we have exactly the same of everything and easy transfer between us?  (include all the NimBLE code + scanning and simplest commands - basically what you are testing with?).
p.s. this github issue is causing browser issues because of it's size... maybe we should move to a new one?

ok, everything is very stable now, but still with the old (&modified) version and non-disconnect -> already connected with rc code above.  Wifi/BLE sharing improved with later 1_0_5_RC4 arduino core...
Could you publish a basic test repo (preferably VSCode/Arduino), and I'll build the simplest test on top, so we have exactly the same of everything and easy transfer between us?  (include all the NimBLE code + scanning and simplest commands - basically what you are testing with?).
p.s. this github issue is causing browser issues because of it's size... maybe we should move to a new one?

Could you publish a basic test repo (preferably VSCode/Arduino), and I'll build the simplest test on top, so we have exactly the same of everything and easy transfer between us? (include all the NimBLE code + scanning and simplest commands - basically what you are testing with?).

I can do this when platformio decides to cooperate with me lol, it's giving me issues atm. However if you want to do this, I have my test setup using the current master branch of arduino-esp32 and change your NimBLE library lib_deps to https://github.com/h2zero/NimBLE-Arduino.git#client-bugfix

Could you publish a basic test repo (preferably VSCode/Arduino), and I'll build the simplest test on top, so we have exactly the same of everything and easy transfer between us? (include all the NimBLE code + scanning and simplest commands - basically what you are testing with?).

I can do this when platformio decides to cooperate with me lol, it's giving me issues atm. However if you want to do this, I have my test setup using the current master branch of arduino-esp32 and change your NimBLE library lib_deps to https://github.com/h2zero/NimBLE-Arduino.git#client-bugfix

i'll wait :).. prefer to modify a repo from you, so I can see how you code it (may see what I'm doing strange!)....

i'll wait :).. prefer to modify a repo from you, so I can see how you code it (may see what I'm doing strange!)....

Sorry, had a busy day. A rare warm and sunny day here in January, good time for a load of firewood.
Good news is, I got platformio to play nice and I found some more related issues that don't seem to show up in Arduino or IDF, possibly due to building in release mode. I have taken care of those temporarily, but I have still managed to make the controller hang. Working on finding why, JTAG time.

Sorry, had a busy day. A rare warm and sunny day here in January, good time for a load of firewood.
Good news is, I got platformio to play nice and I found some more related issues that don't seem to show up in Arduino or IDF, possibly due to building in release mode. I have taken care of those temporarily, but I have still managed to make the controller hang. Working on finding why, JTAG time.

@h2zero , I think I found progress.... Just to make sure for sanity sake, i restored the original "client-bugfix" branch and ran it as is. After several disconnects, same issue, eventually one stays connected (cannot disconnect) while other device is able to disconnect and reconnect, until finally, both remain connected and disconnect() does not drop any of them. I been trying to work on this all weekend and do research on the web, and I saw a comment somewhere on the esp idf forums regarding key stores becomming corrupt to a point where connections refuse to be established. So I been poking around the nimble files and decided to set CONFIG_BT_NIMBLE_NVS_PERSIST to 0 instead of 1. As I write this it is still successfully connect()ing and disconnect()ing without issues! I will keep it running and see how long it holds up, but restoring the client-bugfix branch was a good test to check it as is vs with **define CONFIG_BT_NIMBLE_NVS_PERSIST ** set to 0 :)

@h2zero , I think I found progress.... Just to make sure for sanity sake, i restored the original "client-bugfix" branch and ran it as is. After several disconnects, same issue, eventually one stays connected (cannot disconnect) while other device is able to disconnect and reconnect, until finally, both remain connected and disconnect() does not drop any of them. I been trying to work on this all weekend and do research on the web, and I saw a comment somewhere on the esp idf forums regarding key stores becomming corrupt to a point where connections refuse to be established. So I been poking around the nimble files and decided to set CONFIG_BT_NIMBLE_NVS_PERSIST to 0 instead of 1. As I write this it is still successfully connect()ing and disconnect()ing without issues! I will keep it running and see how long it holds up, but restoring the client-bugfix branch was a good test to check it as is vs with **define CONFIG_BT_NIMBLE_NVS_PERSIST ** set to 0 :)

@tonton81 That's an interesting finding, too bad it didn't work out.
In the mean time I have spent 6 or 8 beers worth of time debugging this over the last couple nights and have come to the conclusion that there is just a bug in the controller I cannot fix. However I have found it's triggers and built a workaround so that the frequency of occurrence as well as the handling of the error has shown satisfactory results. I have just pushed a commit to the
client-bugfix branch please test it and let me know your results.
@btsimonh I have created a new repo with my test code it uses platformio, arduino master branch and the client-bugfix branch of this repo. Very simple app code that guarantees failure on disconnect with the current master and recovers well in the bugfix branch. Check it out and change the mac address to one of your devices.

@tonton81 That's an interesting finding, too bad it didn't work out.
In the mean time I have spent 6 or 8 beers worth of time debugging this over the last couple nights and have come to the conclusion that there is just a bug in the controller I cannot fix. However I have found it's triggers and built a workaround so that the frequency of occurrence as well as the handling of the error has shown satisfactory results. I have just pushed a commit to the
client-bugfix branch please test it and let me know your results.
@btsimonh I have created a new repo with my test code it uses platformio, arduino master branch and the client-bugfix branch of this repo. Very simple app code that guarantees failure on disconnect with the current master and recovers well in the bugfix branch. Check it out and change the mac address to one of your devices.

Just to add another note to this I have found espressif/esp-idf#5105 to be enlightening as to the cause. Unfortunately I don't know if the patch mentioned there is available in ardruino-esp32 rc1.0.5.

Just to add another note to this I have found espressif/esp-idf#5105 to be enlightening as to the cause. Unfortunately I don't know if the patch mentioned there is available in ardruino-esp32 rc1.0.5.

I have been able to reproduce a faster BLE lockup accross previous tests, running disconnects() at 3 sec intervals, and switching the BLE devices power on and off at their power source on and off by hand to a point where I can test the disconnect issue faster rather than waiting up to 10 minutes. Now with the current fix you applied, I can't seem to make it crash that way anymore and I believe that when I see this:
sync: bytes: 24, controller: 0, time_t: 17, Wanted: 186, 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 186 252 63
XBT controller was repowered, setting all channels off...
CRIT NimBLEClient: "Disconnect timed out - resetting host"
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CRIT NimBLEDevice: "Resetting state; reason=12, "
DisCRfIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CDRfIT NimBLEram_lld_pdu_tx_flush HCI packet count mismatch (1, 2)
Scan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
It must be working because it still connects to both devices fine.
It did a total lockup at one point when i was repowering the devices but havn't experienced it yet again, needed to reboot the ESP32 and it was ok again

I have been able to reproduce a faster BLE lockup accross previous tests, running disconnects() at 3 sec intervals, and switching the BLE devices power on and off at their power source on and off by hand to a point where I can test the disconnect issue faster rather than waiting up to 10 minutes. Now with the current fix you applied, I can't seem to make it crash that way anymore and I believe that when I see this:
sync: bytes: 24, controller: 0, time_t: 17, Wanted: 186, 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 186 252 63
XBT controller was repowered, setting all channels off...
CRIT NimBLEClient: "Disconnect timed out - resetting host"
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CRIT NimBLEDevice: "Resetting state; reason=12, "
DisCRfIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CDRfIT NimBLEram_lld_pdu_tx_flush HCI packet count mismatch (1, 2)
Scan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
CRIT NimBLEScan: "Host reset, wait for sync."
It must be working because it still connects to both devices fine.
It did a total lockup at one point when i was repowering the devices but havn't experienced it yet again, needed to reboot the ESP32 and it was ok again

Awesome, thanks for the quick test! The lockup may be due to the scan instance handling of the reset, going to do work on this soon as well. Let me know if you find any more interesting results, looks to be working as intended for the most part.

Awesome, thanks for the quick test! The lockup may be due to the scan instance handling of the reset, going to do work on this soon as well. Let me know if you find any more interesting results, looks to be working as intended for the most part.

on a plus side I added a 3rd XBT controller to test with in multi mode
I added quick detection of "new" XBT modules for quick addition:
ESP monitor:
NEW!! RGB Light was found at MAC address b4:bc:7c:28:9e:22.
Teensy write MAC via CAN to client1 of ESP and spiffs storage, giving this ESP output:
MAC address being changed from ff:ff:ff:ff:ff:ff to b4:bc:7c:28:9e:22 on controller 1...
2 previous controllers were disconnected, and when all 3 connected, the 2 last were sync while the 3rd (new one at default white) was initialized to default off state
Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from f0:b5:d1:8f:b6:b8
CanID: 0xFADE, Free Heap: 253612, debug refresh time: 2001
XBT 0: disconnected
XBT 1: disconnected
XBT 2: disconnected
XBT 3: disconnected
Connected to f0:b5:d1:8f:ba:e5
Colors already set, synchronized with XBT controller.
Connected to b4:bc:7c:28:9e:22
XBT controller was repowered, setting all channels off...
Connected to f0:b5:d1:8f:b6:b8
Colors already set, synchronized with XBT controller.
CanID: 0xFADE, Free Heap: 253444, debug refresh time: 2001
XBT 0: connected
XBT 1: connected
XBT 2: connected
XBT 3: disconnected
The reason I use spiffs for the MAC storage is for reboot address retentions and remote programming over CAN :)

on a plus side I added a 3rd XBT controller to test with in multi mode
I added quick detection of "new" XBT modules for quick addition:
ESP monitor:
NEW!! RGB Light was found at MAC address b4:bc:7c:28:9e:22.
Teensy write MAC via CAN to client1 of ESP and spiffs storage, giving this ESP output:
MAC address being changed from ff:ff:ff:ff:ff:ff to b4:bc:7c:28:9e:22 on controller 1...
2 previous controllers were disconnected, and when all 3 connected, the 2 last were sync while the 3rd (new one at default white) was initialized to default off state
Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from f0:b5:d1:8f:b6:b8
CanID: 0xFADE, Free Heap: 253612, debug refresh time: 2001
XBT 0: disconnected
XBT 1: disconnected
XBT 2: disconnected
XBT 3: disconnected
Connected to f0:b5:d1:8f:ba:e5
Colors already set, synchronized with XBT controller.
Connected to b4:bc:7c:28:9e:22
XBT controller was repowered, setting all channels off...
Connected to f0:b5:d1:8f:b6:b8
Colors already set, synchronized with XBT controller.
CanID: 0xFADE, Free Heap: 253444, debug refresh time: 2001
XBT 0: connected
XBT 1: connected
XBT 2: connected
XBT 3: disconnected
The reason I use spiffs for the MAC storage is for reboot address retentions and remote programming over CAN :)

Nice, looks to be working well for you?

Nice, looks to be working well for you?

So far still running ! :)

So far still running ! :)

Another thing I see here, controller was disconnected before the event went through, this would feed bad data into my array, so I verify some data in the array to confirm if it's a good or bad data, then immediately disconnect so it can reconnect.
bad data:
Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Disconnected from f0:b5:d1:8f:b6:b8
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
Disconnected from f0:b5:d1:8f:ba:e5
sync: bytes: 24, controller: 0, Wanted: 0, 0 26 252 63 8 36 13 128 48 137 252 63 1 229 186 143 124 12 173 50 0 0 0 0
good data:
sync: bytes: 24, controller: 0, Wanted: 68, 1 226 205 192 1 1 0 0 0 1 1 0 0 0 1 1 1 0 0 0 0 68 182 0

Another thing I see here, controller was disconnected before the event went through, this would feed bad data into my array, so I verify some data in the array to confirm if it's a good or bad data, then immediately disconnect so it can reconnect.
bad data:
Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Disconnected from f0:b5:d1:8f:b6:b8
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
Disconnected from f0:b5:d1:8f:ba:e5
sync: bytes: 24, controller: 0, Wanted: 0, 0 26 252 63 8 36 13 128 48 137 252 63 1 229 186 143 124 12 173 50 0 0 0 0
good data:
sync: bytes: 24, controller: 0, Wanted: 68, 1 226 205 192 1 1 0 0 0 1 1 0 0 0 1 1 1 0 0 0 0 68 182 0

Okay, just a note, for the readValue issue (well not per say, but the results of it)
I wrapped 2 connection calls around the services:
if ( !XBT_client[controller]->isConnected() ) {
Serial.println("");
Serial.println("");
Serial.println("***************** CLIENT NO CONNECTED !! **************");
Serial.println("");
Serial.println("");
return;
}
NimBLERemoteService* _service = XBT_client[controller]->getService((uint16_t)0xFFD0); /* "0000ffd0-0000-1000-8000-00805f9b34fb" */
if (_service == nullptr) {
XBT_client[controller]->disconnect();
return;
}
XBT_characteristic[controller] = _service->getCharacteristic((uint16_t)0xFFD1); /* "0000ffd1-0000-1000-8000-00805f9b34fb" */
if (XBT_characteristic[controller] == nullptr) {
XBT_client[controller]->disconnect();
return;
}
if ( !XBT_client[controller]->isConnected() ) {
Serial.println("");
Serial.println("");
Serial.println("***************** CLIENT NO CONNECTED 2 !! ");
Serial.println("");
Serial.println("************");
return;
}
The CLIENT NO CONNECTED 2 !! is never fired, which means, somehow, between         XBT_client[i]->connect(XBT_controller[i]); and the service management function sync_XBT_controllers(i); I guess the connection state was not updated before accessing the services (timing), or the connection failed. At least I don't need to monitor the readValue array if I catch it earlier

Okay, just a note, for the readValue issue (well not per say, but the results of it)
I wrapped 2 connection calls around the services:
if ( !XBT_client[controller]->isConnected() ) {
Serial.println("");
Serial.println("");
Serial.println("***************** CLIENT NO CONNECTED !! **************");
Serial.println("");
Serial.println("");
return;
}
NimBLERemoteService* _service = XBT_client[controller]->getService((uint16_t)0xFFD0); /* "0000ffd0-0000-1000-8000-00805f9b34fb" */
if (_service == nullptr) {
XBT_client[controller]->disconnect();
return;
}
XBT_characteristic[controller] = _service->getCharacteristic((uint16_t)0xFFD1); /* "0000ffd1-0000-1000-8000-00805f9b34fb" */
if (XBT_characteristic[controller] == nullptr) {
XBT_client[controller]->disconnect();
return;
}
if ( !XBT_client[controller]->isConnected() ) {
Serial.println("");
Serial.println("");
Serial.println("***************** CLIENT NO CONNECTED 2 !! ");
Serial.println("");
Serial.println("************");
return;
}
The CLIENT NO CONNECTED 2 !! is never fired, which means, somehow, between         XBT_client[i]->connect(XBT_controller[i]); and the service management function sync_XBT_controllers(i); I guess the connection state was not updated before accessing the services (timing), or the connection failed. At least I don't need to monitor the readValue array if I catch it earlier

in 25 Minutes i get this lockup:
CanID: 0xFADE, Free Heap: 254416, debug refresh time: 2001
XBT 0: connected
XBT 1: connected
XBT 2: connected
XBT 3: disconnected
Time: 1464733
Time: 1464734
Time: 1464734
Time: 1464734
Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Connected to f0:b5:d1:8f:ba:e5
CRIT NimBLEClient: "Disconnect timed out - resetting host"
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CRIT NimBLEDevice: "Resetting state; reason=12, "
Disconnected from f0:b5:d1:8f:ba:e5
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
Disconnected from f0:b5:d1:8f:b6:b8
Gonna enable Debug mode and let it run again

in 25 Minutes i get this lockup:
CanID: 0xFADE, Free Heap: 254416, debug refresh time: 2001
XBT 0: connected
XBT 1: connected
XBT 2: connected
XBT 3: disconnected
Time: 1464733
Time: 1464734
Time: 1464734
Time: 1464734
Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Connected to f0:b5:d1:8f:ba:e5
CRIT NimBLEClient: "Disconnect timed out - resetting host"
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CRIT NimBLEDevice: "Resetting state; reason=12, "
Disconnected from f0:b5:d1:8f:ba:e5
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
Disconnected from f0:b5:d1:8f:b6:b8
Gonna enable Debug mode and let it run again

Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Disconnected from f0:b5:d1:8f:b6:b8
Connected to f0:b5:d1:8f:ba:e5
sync: bytes: 24, controller: 0, Wanted: 189, 1 12 124 189 1 1 0 0 0 1 1 0 0 0 1 1 1 0 0 0 0 189 252 63
Colors already set, synchronized with XBT controller.
Connected to b4:bc:7c:28:9e:22
sync: bytes: 24, controller: 1, Wanted: 189, 1 12 124 189 1 1 0 0 0 1 1 0 0 0 1 1 1 0 0 0 0 189 252 63
Colors already set, synchronized with XBT controller.
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
Disconnected from f0:b5:d1:8f:b6:b8 <-- controller 2 address

Interesting that.
We should not be getting a disconnect event for a connection that is already disconnected. This has something to do with the controller issue as lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2) is the symptom. However the app should never see this as it should not be processed by the event handler. The only thing I can think of that would allow that to happen is if the event came with a connection ID of BLE_HS_CONN_HANDLE_NONE which is not currently checked. Would be nice to confirm that.

if ( XBT_client[i]->connect(XBT_controller[i]) ) sync_XBT_controllers(i); // process services only on true
I am just surprised when it was disconnected, the service checks didn't return nullptr, causing the readValue to continue and return data from somewhere

Not really a work around, but a proper check. The reason the services etc. are still accessible is due to having created instances of remoteX in a vector last time they were asked for. We keep a copy so we don't need to keep asking the peripheral for them and wasting time/energy and saves battery power. You can call NimBLEClient::deleteServices() in the disconnect callback or before reconnecting if you don't want this, just be aware of the reduced performance if you do this.

Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Connected to f0:b5:d1:8f:ba:e5 <-- callback print, looks like callback event fired during a timeout
CRIT NimBLEClient: "Disconnect timed out - resetting host"
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CRIT NimBLEDevice: "Resetting state; reason=12, "
Disconnected from f0:b5:d1:8f:ba:e5
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
Disconnected from f0:b5:d1:8f:b6:b8

I don't have any ideas on the lockup right now, but I do think the timeout message needs to print the address of the device to help debug this.

Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Disconnected from f0:b5:d1:8f:b6:b8
Connected to f0:b5:d1:8f:ba:e5
sync: bytes: 24, controller: 0, Wanted: 189, 1 12 124 189 1 1 0 0 0 1 1 0 0 0 1 1 1 0 0 0 0 189 252 63
Colors already set, synchronized with XBT controller.
Connected to b4:bc:7c:28:9e:22
sync: bytes: 24, controller: 1, Wanted: 189, 1 12 124 189 1 1 0 0 0 1 1 0 0 0 1 1 1 0 0 0 0 189 252 63
Colors already set, synchronized with XBT controller.
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
Disconnected from f0:b5:d1:8f:b6:b8 <-- controller 2 address

Interesting that.
We should not be getting a disconnect event for a connection that is already disconnected. This has something to do with the controller issue as lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2) is the symptom. However the app should never see this as it should not be processed by the event handler. The only thing I can think of that would allow that to happen is if the event came with a connection ID of BLE_HS_CONN_HANDLE_NONE which is not currently checked. Would be nice to confirm that.

if ( XBT_client[i]->connect(XBT_controller[i]) ) sync_XBT_controllers(i); // process services only on true
I am just surprised when it was disconnected, the service checks didn't return nullptr, causing the readValue to continue and return data from somewhere

Not really a work around, but a proper check. The reason the services etc. are still accessible is due to having created instances of remoteX in a vector last time they were asked for. We keep a copy so we don't need to keep asking the peripheral for them and wasting time/energy and saves battery power. You can call NimBLEClient::deleteServices() in the disconnect callback or before reconnecting if you don't want this, just be aware of the reduced performance if you do this.

Disconnected from f0:b5:d1:8f:ba:e5
Disconnected from b4:bc:7c:28:9e:22
Connected to f0:b5:d1:8f:ba:e5 <-- callback print, looks like callback event fired during a timeout
CRIT NimBLEClient: "Disconnect timed out - resetting host"
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CRIT NimBLEDevice: "Resetting state; reason=12, "
Disconnected from f0:b5:d1:8f:ba:e5
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
Disconnected from f0:b5:d1:8f:b6:b8

I don't have any ideas on the lockup right now, but I do think the timeout message needs to print the address of the device to help debug this.

Found the cause of the lockup. I last minute edited out a return code check and return but forgot to change the switch breaks to return. I just pushed that fix and added the address to the timeout rest message.

Found the cause of the lockup. I last minute edited out a return code check and return but forgot to change the switch breaks to return. I just pushed that fix and added the address to the timeout rest message.

Before I test more, this is the lockup with Debug enabled from last night
D NimBLERemoteCharacteristic: ">> writeValue(), length: 20"
D NimBLEScan: "discovery complete; reason=0"
D NimBLEScan: ">> start(duration=1)"
D NimBLEScan: "<< start()"
D NimBLEClient: ">> connect(b4:bc:7c:28:9e:22)"
D NimBLEScan: ">> stop()"
D NimBLEScan: "<< stop()"
D NimBLEClient: "Got Client event "
D NimBLEClient: "Connection established"
D NimBLEClient: "Got Client event "
I NimBLEClient: "mtu update event; conn_handle=1 mtu=23"
D NimBLEClient: ">> deleteServices"
D NimBLERemoteService: ">> deleteCharacteristics"
D NimBLERemoteCharacteristic: ">> deleteDescriptors"
D NimBLERemoteCharacteristic: "<< deleteDescriptors"
D NimBLERemoteService: "<< deleteCharacteristics"
D NimBLEClient: "<< deleteServices"
Connected to b4:bc:7c:28:9e:22
D NimBLEClient: "<< connect()"
D NimBLEClient: ">> getService: uuid: 0xffd0"
D NimBLEClient: ">> retrieveServices"
D NimBLEClient: "Service Discovered >> status: 14 handle: -1"
D NimBLEClient: "<< << Service Discovered"
D NimBLEClient: "<< retrieveServices"
D NimBLEClient: ">> getService: uuid: 0000ffd0-0000-1000-8000-00805f9b34fb"
D NimBLEClient: ">> retrieveServices"
D NimBLEClient: "Service Discovered >> status: 0 handle: 35"
D NimBLERemoteService: ">> NimBLERemoteService()"
D NimBLERemoteService: "<< NimBLERemoteService(): 0000ffd0-0000-1000-8000-00805f9b34fb"
D NimBLEClient: "Service Discovered >> status: 14 handle: -1"
D NimBLEClient: "<< << Service Discovered"
D NimBLEClient: "<< retrieveServices"
D NimBLERemoteService: ">> getCharacteristic: uuid: 0xffd1"
D NimBLERemoteService: ">> retrieveCharacteristics() for service: 0000ffd0-0000-1000-8000-00805f9b34fb"
D NimBLERemoteService: "Characteristic Discovered >> status: 14 handle: -1"
D NimBLERemoteService: "<< Characteristic Discovered"
D NimBLERemoteService: "<< retrieveCharacteristics()"
D NimBLERemoteService: ">> getCharacteristic: uuid: 0000ffd1-0000-1000-8000-00805f9b34fb"
D NimBLERemoteService: ">> retrieveCharacteristics() for service: 0000ffd0-0000-1000-8000-00805f9b34fb"
D NimBLERemoteService: "Characteristic Discovered >> status: 0 handle: 37"
D NimBLERemoteCharacteristic: ">> NimBLERemoteCharacteristic()"
D NimBLERemoteCharacteristic: "<< NimBLERemoteCharacteristic(): 0000ffd1-0000-1000-8000-00805f9b34fb"
D NimBLERemoteService: "Characteristic Discovered >> status: 14 handle: -1"
D NimBLERemoteService: "<< Characteristic Discovered"
D NimBLERemoteService: "<< retrieveCharacteristics()"
D NimBLERemoteCharacteristic: ">> readValue(): uuid: 0000ffd1-0000-1000-8000-00805f9b34fb, handle: 37 0x25"
I NimBLERemoteCharacteristic: "Read complete; status=0 conn_handle=1"
D NimBLERemoteCharacteristic: "Got 20 bytes"
I NimBLERemoteCharacteristic: "Read complete; status=14 conn_handle=1"
D NimBLERemoteCharacteristic: "<< readValue length: 20 rc=0"
sCR0I1TC NimBLEClient: "Disconnect timed out - resetting host"
D NimBLERemoteCharacteristic: ">> writeValue(), length: 20"
D NimBLEClient: "Got Client event "
D NimBLEClient: ">> connect(f0:b5:d1:8f:b6:b8)"
I NimBLEClient: "disconnect; reason=12, "
E NimBLEClient: "Failed to connect to f0:b5:d1:8f:b6:b8, rc=22; "
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
CRIT NimBLEDevice: "Resetting state; reason=12, "
Disconnected from b4:bc:7c:28:9e:22
D NimBLEClient: "Got Client event "
I NimBLEClient: "disconnect; reason=12, "
CRIT NimBLEClient: "Disconnect - host reset, rc=12"
Disconnected from f0:b5:d1:8f:ba:e5
I NimBLEDevice: "NimBle host synced."
D NimBLEScan: ">> start(duration=1)"
D NimBLEScan: "<< start()"
I NimBLEScan: "NEW DEVICE FOUND: f0:b5:d1:8f:ba:e5"
D NimBLEAdvertisedDevice: "payload:<PHONE_NUMBER>0c1faff6aadfddb0cb425cdc7b2a598b07ffe5ba8fd1b5f0"
I NimBLEScan: "UPDATING PREVIOUSLY FOUND DEVICE: f0:b5:d1:8f:ba:e5"