Differentiate disconnect w/ IO-Error, i.e. DBTDevice shall not issue HCI nor Mgmt disconnect (device gone)

It has shown that the extreme 6-9s delay in forced disconnect (device shutdown)
is caused by the HCI and Mgmt disconnect command. Both fail, always.

Hence, in case of a GATT send error or short read-reply timeout (ringbuffer.getBlocking(500ms))
we can cleanup the device w/o explicit disconnect command.

+++

The usual disconnect signal from a device forced shutdown is as follows:
  L2CAP send or GATT read-reply -> Device -> HCI(1) + Mgmt(2)

(1) HCI disconnect skipped if IO-Error
(2) Mgmt disconnect skipped if IO-Error, but sends DISCONNECT event

+++

Mgmt and GATTHandler also differentiate timeouts,
lenghthly 3s for the ringbuffer read w/o any impact and 1s (mgmt) or 500ms (gatt) for command replies
on the user thread.

This leads to fast DISCONNECT events for the user and actual device cleanup.
Subsequent connection works w/o issues.

If using HCI connect via discovery (not whitelist),
the turnaround time from forced disconnect to next connect is below 1s.
However, using whitelist, the subsequent connect after the forced disconnect
consumes 'a few seconds' and hence is seemingly not suitable for a responsive system (???).
The latter is true with or without Mgmt disconnect attempts!

Misc:
- L2CAPComm disconnect: Show potention pthread_kill error
- HCIComm send_req/send: Refine ERR_PRINT, remove unsused case HCI_EV_REMOTE_NAME

6 files changed, 90 insertions, 65 deletions

diff --git a/src/direct_bt/DBTAdapter.cpp b/src/direct_bt/DBTAdapter.cpp
index 47465254..308d4be6 100644
--- a/src/direct_bt/DBTAdapter.cpp
+++ b/src/direct_bt/DBTAdapter.cpp
@@ -557,6 +557,7 @@ bool DBTAdapter::mgmtEvDeviceConnectedCB(std::shared_ptr<MgmtEvent> e) {
         if( 0 < new_connect ) {
             addConnectedDevice(device); // track it
         }
+        device->notifyConnected();
         int i=0;
         for_each_idx_mtx(mtx_statusListenerList, statusListenerList, [&](std::shared_ptr<AdapterStatusListener> &l) {
             try {
diff --git a/src/direct_bt/DBTDevice.cpp b/src/direct_bt/DBTDevice.cpp
index 8146d3cb..fdf242e9 100644
--- a/src/direct_bt/DBTDevice.cpp
+++ b/src/direct_bt/DBTDevice.cpp
@@ -45,6 +45,7 @@ using namespace direct_bt;
 DBTDevice::DBTDevice(DBTAdapter & a, EInfoReport const & r)
 : adapter(a), ts_creation(r.getTimestamp()), address(r.getAddress()), addressType(r.getAddressType())
 {
+    isConnected = false;
     if( !r.isSet(EIRDataType::BDADDR) ) {
         throw IllegalArgumentException("DBTDevice ctor: Address not set: "+r.toString(), E_FILE_LINE);
     }
@@ -119,7 +120,8 @@ std::string DBTDevice::toString(bool includeDiscoveredServices) const {
     const uint64_t t0 = getCurrentMilliseconds();
     std::string msdstr = nullptr != msd ? msd->toString() : "MSD[null]";
     std::string out("Device[address["+getAddressString()+", "+getBDAddressTypeString(getAddressType())+"], name['"+name+
-            "'], age "+std::to_string(t0-ts_creation)+" ms, lup "+std::to_string(t0-ts_update)+" ms, rssi "+std::to_string(getRSSI())+
+            "'], age "+std::to_string(t0-ts_creation)+" ms, lup "+std::to_string(t0-ts_update)+
+            " ms, connected "+std::to_string(isConnected)+", rssi "+std::to_string(getRSSI())+
             ", tx-power "+std::to_string(tx_power)+
             ", appearance "+uint16HexString(static_cast<uint16_t>(appearance))+" ("+AppearanceCatToString(appearance)+
             "), "+msdstr+", "+javaObjectToString()+"]");
@@ -339,40 +341,66 @@ uint16_t DBTDevice::connectDefault()
     }
 }
 
+void DBTDevice::notifyConnected() {
+    DBG_PRINT("DBTDevice::notifyConnected: %s", toString().c_str());
+    isConnected = true;
+}
+
 void DBTDevice::notifyDisconnected() {
-    DBG_PRINT("DBTDevice::notifyDisconnected: disconnecting ...");
-    disconnect(false); // coming from manager disconnect, but ensure cleaning up!
+    DBG_PRINT("DBTDevice::notifyDisconnected: %s", toString().c_str());
+    try {
+        // coming from manager disconnect, ensure cleaning up!
+        disconnect(true /* sentFromManager */, false /* ioErrorCause */);
+    } catch (std::exception &e) {
+        ERR_PRINT("Exception caught on %s: %s", toString().c_str(), e.what());
+    }
+    isConnected = false;
 }
 
-void DBTDevice::disconnect(const bool disconnectManager, const uint8_t reason) {
-    DBG_PRINT("DBTDevice::disconnect: disconnectManager %d, gattHandler %d, hciConnHandle %d",
-            disconnectManager, (nullptr != gattHandler), (0 != hciConnHandle));
+void DBTDevice::disconnect(const bool sentFromManager, const bool ioErrorCause, const uint8_t reason) {
+    DBG_PRINT("DBTDevice::disconnect: isConnected %d, sentFromManager %d, ioError %d, gattHandler %d, hciConnHandle %d",
+            isConnected.load(), sentFromManager, ioErrorCause, (nullptr != gattHandler), (0 != hciConnHandle));
     disconnectGATT();
 
     const std::lock_guard<std::recursive_mutex> lock(adapter.mtx_hci); // RAII-style acquire and relinquish via destructor
     std::shared_ptr<HCIComm> hciComm = adapter.getHCI();
 
+    if( !isConnected ) {
+        DBG_PRINT("DBTDevice::disconnect: Skip disconnect: Not connected: %s", toString().c_str());
+        goto exit;
+    }
+    isConnected = false;
+
+    if( ioErrorCause ) {
+        DBG_PRINT("DBTDevice::disconnect: Skip HCI disconnect: IO Error: %s", toString().c_str());
+        goto skip_hci_disconnect;
+    }
+
     if( 0 == hciConnHandle ) {
-        DBG_PRINT("DBTDevice::disconnect: HCI not connected");
+        DBG_PRINT("DBTDevice::disconnect: Skip HCI disconnect: HCI not connected: %s", toString().c_str());
         goto skip_hci_disconnect;
     }
 
     if( nullptr == hciComm || !hciComm->isOpen() ) {
-        DBG_PRINT("DBTDevice::disconnect: Adapter's HCIComm not open: %s", toString().c_str());
-    } else {
-        if( !hciComm->disconnect(hciConnHandle, reason) ) {
-            DBG_PRINT("DBTDevice::disconnect: handle 0x%X, errno %d %s", hciConnHandle, errno, strerror(errno));
-        }
+        DBG_PRINT("DBTDevice::disconnect: Skip HCI disconnect: HCI not Open: %s", toString().c_str());
+        goto skip_hci_disconnect;
+    }
+
+    if( !hciComm->disconnect(hciConnHandle, reason) ) {
+        DBG_PRINT("DBTDevice::disconnect: handle 0x%X, errno %d %s", hciConnHandle, errno, strerror(errno));
     }
-    hciConnHandle = 0;
 
 skip_hci_disconnect:
-    if( disconnectManager ) {
+    hciConnHandle = 0;
+
+    if( !sentFromManager ) {
         // Also issue mngr.disconnect on non-HCI connect (whitelist),
         // which will also send the DISCONNECT event.
         DBTManager & mngr = adapter.getManager();
-        mngr.disconnect(adapter.dev_id, address, addressType, reason);
+        mngr.disconnect(ioErrorCause, adapter.dev_id, address, addressType, reason);
     }
+
+exit:
     adapter.removeConnectedDevice(*this);
 }
 
@@ -381,7 +409,7 @@ void DBTDevice::remove() {
     releaseSharedInstance();
 }
 
-std::shared_ptr<GATTHandler> DBTDevice::connectGATT(int timeoutMS) {
+std::shared_ptr<GATTHandler> DBTDevice::connectGATT(int replyTimeoutMS) {
     std::shared_ptr<DBTDevice> sharedInstance = getSharedInstance();
     if( nullptr == sharedInstance ) {
         throw InternalError("DBTDevice::connectGATT: Device unknown to adapter and not tracked: "+toString(), E_FILE_LINE);
@@ -394,7 +422,7 @@ std::shared_ptr<GATTHandler> DBTDevice::connectGATT(int timeoutMS) {
         }
         gattHandler = nullptr;
     }
-    gattHandler = std::shared_ptr<GATTHandler>(new GATTHandler(sharedInstance, timeoutMS));
+    gattHandler = std::shared_ptr<GATTHandler>(new GATTHandler(sharedInstance, replyTimeoutMS));
     if( !gattHandler->connect() ) {
         DBG_PRINT("DBTDevice::connectGATT: Connection failed");
         gattHandler = nullptr;
diff --git a/src/direct_bt/DBTManager.cpp b/src/direct_bt/DBTManager.cpp
index 5f38b9a4..b8ac12fa 100644
--- a/src/direct_bt/DBTManager.cpp
+++ b/src/direct_bt/DBTManager.cpp
@@ -165,7 +165,7 @@ std::shared_ptr<MgmtEvent> DBTManager::sendWithReply(MgmtCommand &req) {
     // Ringbuffer read is thread safe
     int retry = 3;
     while( 0 < retry ) {
-        std::shared_ptr<MgmtEvent> res = mgmtEventRing.getBlocking(MGMT_READER_THREAD_POLL_TIMEOUT);
+        std::shared_ptr<MgmtEvent> res = mgmtEventRing.getBlocking(MGMT_COMMAND_REPLY_TIMEOUT);
         // std::shared_ptr<MgmtEvent> res = receiveNext();
         if( nullptr == res ) {
             errno = ETIMEDOUT;
@@ -607,14 +607,19 @@ uint16_t DBTManager::create_connection(const int dev_id,
     return 0;
 }
 
-bool DBTManager::disconnect(const int dev_id, const EUI48 &peer_bdaddr, const BDAddressType peer_mac_type, const uint8_t reason) {
-    MgmtDisconnectCmd req(dev_id, peer_bdaddr, peer_mac_type);
-    std::shared_ptr<MgmtEvent> res = sendWithReply(req);
+bool DBTManager::disconnect(const bool ioErrorCause,
+                            const int dev_id, const EUI48 &peer_bdaddr, const BDAddressType peer_mac_type,
+                            const uint8_t reason) {
     bool bres = false;
-    if( nullptr != res && res->getOpcode() == MgmtEvent::Opcode::CMD_COMPLETE ) {
-        const MgmtEvtCmdComplete &res1 = *static_cast<const MgmtEvtCmdComplete *>(res.get());
-        if( MgmtStatus::SUCCESS == res1.getStatus() ) {
-            bres = true;
+
+    if( !ioErrorCause ) {
+        MgmtDisconnectCmd req(dev_id, peer_bdaddr, peer_mac_type);
+        std::shared_ptr<MgmtEvent> res = sendWithReply(req);
+        if( nullptr != res && res->getOpcode() == MgmtEvent::Opcode::CMD_COMPLETE ) {
+            const MgmtEvtCmdComplete &res1 = *static_cast<const MgmtEvtCmdComplete *>(res.get());
+            if( MgmtStatus::SUCCESS == res1.getStatus() ) {
+                bres = true;
+            }
         }
     }
     // explicit disconnected event anyways
diff --git a/src/direct_bt/GATTHandler.cpp b/src/direct_bt/GATTHandler.cpp
index 81a03ef8..61256a13 100644
--- a/src/direct_bt/GATTHandler.cpp
+++ b/src/direct_bt/GATTHandler.cpp
@@ -60,6 +60,7 @@ extern "C" {
 
 #include "GATTHandler.hpp"
 
+#include "HCIComm.hpp"
 #include "DBTTypes.hpp"
 #include "DBTDevice.hpp"
 
@@ -97,7 +98,7 @@ GATTHandler::State GATTHandler::validateState() {
             //        ", l2cap[open "+std::to_string(b)+", state "+l2cap->getStateString()+"]", E_FILE_LINE);
             ERR_PRINT("Inconsistent open state: GattHandler[open %d, %s], l2cap[open [%d, %d], state %s]: %s",
                     a, getStateString().c_str(), b, c, l2cap.getStateString().c_str(), deviceString.c_str());
-            disconnect(); // state -> Disconnected
+            disconnect(true /* ioErrorCause */); // state -> Disconnected
         }
     }
     return state;
@@ -169,6 +170,7 @@ bool GATTHandler::getSendIndicationConfirmation() {
 }
 
 void GATTHandler::l2capReaderThreadImpl() {
+    bool ioErrorCause = false;
     l2capReaderShallStop = false;
     l2capReaderRunning = true;
     INFO_PRINT("l2capReaderThreadImpl Started");
@@ -182,7 +184,7 @@ void GATTHandler::l2capReaderThreadImpl() {
             break;
         }
 
-        len = l2cap.read(rbuffer.get_wptr(), rbuffer.getSize(), timeoutMS);
+        len = l2cap.read(rbuffer.get_wptr(), rbuffer.getSize(), L2CAP_READER_THREAD_POLL_TIMEOUT);
         if( 0 < len ) {
             const AttPDUMsg * attPDU = AttPDUMsg::getSpecialized(rbuffer.get_ptr(), len);
             const AttPDUMsg::Opcode opc = attPDU->getOpcode();
@@ -247,17 +249,18 @@ void GATTHandler::l2capReaderThreadImpl() {
         } else if( ETIMEDOUT != errno && !l2capReaderShallStop ) { // expected exits
             ERR_PRINT("GATTHandler::l2capReaderThread: l2cap read error -> Stop");
             l2capReaderShallStop = true;
+            ioErrorCause = true;
         }
     }
 
     INFO_PRINT("l2capReaderThreadImpl Ended");
     l2capReaderRunning = false;
-    disconnect();
+    disconnect(ioErrorCause);
 }
 
-GATTHandler::GATTHandler(const std::shared_ptr<DBTDevice> &device, const int timeoutMS)
+GATTHandler::GATTHandler(const std::shared_ptr<DBTDevice> &device, const int replyTimeoutMS)
 : device(device), deviceString(device->getAddressString()), rbuffer(ClientMaxMTU),
-  l2cap(device, L2CAP_PSM_UNDEF, L2CAP_CID_ATT), timeoutMS(timeoutMS),
+  l2cap(device, L2CAP_PSM_UNDEF, L2CAP_CID_ATT), replyTimeoutMS(replyTimeoutMS),
   state(Disconnected), attPDURing(ATTPDU_RING_CAPACITY),
   l2capReaderThreadId(0), l2capReaderRunning(false), l2capReaderShallStop(false),
   serverMTU(DEFAULT_MIN_ATT_MTU), usedMTU(DEFAULT_MIN_ATT_MTU)
@@ -265,7 +268,7 @@ GATTHandler::GATTHandler(const std::shared_ptr<DBTDevice> &device, const int tim
 
 GATTHandler::~GATTHandler() {
     eventListenerList.clear();
-    disconnect();
+    disconnect(false /* ioErrorCause */);
 }
 
 bool GATTHandler::connect() {
@@ -295,13 +298,13 @@ bool GATTHandler::connect() {
     usedMTU = std::min((int)ClientMaxMTU, (int)serverMTU);
     if( 0 == serverMTU ) {
         ERR_PRINT("GATTHandler::connect: Zero serverMTU -> disconnect: %s", deviceString.c_str());
-        disconnect();
+        disconnect(false /* ioErrorCause */);
         return false;
     }
     return true;
 }
 
-bool GATTHandler::disconnect() {
+bool GATTHandler::disconnect(const bool ioErrorCause) {
     DBG_PRINT("GATTHandler::disconnect: GattHandler[%s], l2cap[%s], connected %d, device-value %d",
                 getStateString().c_str(), l2cap.getStateString().c_str(),
                 (Disconnected < state), (nullptr != device));
@@ -321,7 +324,10 @@ bool GATTHandler::disconnect() {
     if( l2capReaderRunning ) {
         l2capReaderShallStop = true;
         if( !is_l2capReader && 0 != tid_l2capReader ) {
-            pthread_kill(tid_l2capReader, SIGALRM);
+            int kerr;
+            if( 0 != ( kerr = pthread_kill(tid_l2capReader, SIGALRM) ) ) {
+                ERR_PRINT("GATTHandler::disconnect: pthread_kill %p FAILED: %d", (void*)tid_l2capReader, kerr);
+            }
         }
     }
 
@@ -329,7 +335,12 @@ bool GATTHandler::disconnect() {
     state = Disconnected;
 
     if( nullptr != device ) {
-        device->disconnect(); // cleanup device resources, proper connection state
+        // Cleanup device resources, proper connection state
+        // Intentionally giving the POWER_OFF reason for the device in case of ioErrorCause!
+        const uint8_t reason = ioErrorCause ?
+                               static_cast<uint8_t>(HCIErrorCode::REMOTE_DEVICE_TERMINATED_CONNECTION_POWER_OFF) :
+                               static_cast<uint8_t>(HCIErrorCode::REMOTE_USER_TERMINATED_CONNECTION);
+        device->disconnect(false /* sentFromManager */, ioErrorCause, reason);
     }
 
     DBG_PRINT("GATTHandler::disconnect End");
@@ -353,14 +364,14 @@ void GATTHandler::send(const AttPDUMsg & msg) {
     if( 0 > res ) {
         ERR_PRINT("GATTHandler::send: l2cap write error -> disconnect: %s to %s", msg.toString().c_str(), deviceString.c_str());
         state = Error;
-        disconnect(); // state -> Disconnected
+        disconnect(true /* ioErrorCause */); // state -> Disconnected
         throw BluetoothException("GATTHandler::send: l2cap write error: req "+msg.toString()+" to "+deviceString, E_FILE_LINE);
     }
     if( res != msg.pdu.getSize() ) {
         ERR_PRINT("GATTHandler::send: l2cap write count error, %d != %d: %s -> disconnect: %s",
                 res, msg.pdu.getSize(), msg.toString().c_str(), deviceString.c_str());
         state = Error;
-        disconnect(); // state -> Disconnected
+        disconnect(true /* ioErrorCause */); // state -> Disconnected
         throw BluetoothException("GATTHandler::send: l2cap write count error, "+std::to_string(res)+" != "+std::to_string(res)
                                  +": "+msg.toString()+" -> disconnect: "+deviceString, E_FILE_LINE);
     }
@@ -374,14 +385,14 @@ std::shared_ptr<const AttPDUMsg> GATTHandler::sendWithReply(const AttPDUMsg & ms
     if( nullptr == res ) {
         errno = ETIMEDOUT;
         ERR_PRINT("GATTHandler::send: nullptr result (timeout): req %s to %s", msg.toString().c_str(), deviceString.c_str());
-        disconnect();
+        disconnect(true /* ioErrorCause */);
         throw BluetoothException("GATTHandler::send: nullptr result (timeout): req "+msg.toString()+" to "+deviceString, E_FILE_LINE);
     }
     return res;
 }
 
 std::shared_ptr<const AttPDUMsg> GATTHandler::receiveNext() {
-    return attPDURing.getBlocking(timeoutMS);
+    return attPDURing.getBlocking(replyTimeoutMS);
 }
 
 uint16_t GATTHandler::exchangeMTU(const uint16_t clientMaxMTU) {
diff --git a/src/direct_bt/HCIComm.cpp b/src/direct_bt/HCIComm.cpp
index d82bba5e..0a2b2618 100644
--- a/src/direct_bt/HCIComm.cpp
+++ b/src/direct_bt/HCIComm.cpp
@@ -370,7 +370,7 @@ HCIErrorCode HCIComm::send_req(const uint16_t opcode, const void *command, const
 #else
             while ((n = poll(&p, 1, _timeoutMS)) < 0) {
 #endif
-			    ERR_PRINT("hci_send_req: poll");
+			    ERR_PRINT("HCIComm::send_req(dev_id %d, channel %d): poll: res %d", dev_id, channel, n);
 				if (errno == EAGAIN || errno == EINTR) {
 					continue;
 				}
@@ -392,7 +392,7 @@ HCIErrorCode HCIComm::send_req(const uint16_t opcode, const void *command, const
 		int len;
 
 		while ((len = ::read(_dd, buf, sizeof(buf))) < 0) {
-		    ERR_PRINT("hci_send_req: read: res %d", len);
+		    ERR_PRINT("HCIComm::send_req(dev_id %d, channel %d): read: res %d", dev_id, channel, len);
 			if (errno == EAGAIN || errno == EINTR) {
 				continue;
 			}
@@ -456,29 +456,6 @@ HCIErrorCode HCIComm::send_req(const uint16_t opcode, const void *command, const
                         rlen, bytesHexString((uint8_t*)ptr, 0, rlen, false /* lsbFirst */, true /* leading0X */).c_str());
                 goto done;
 		    }
-		case HCI_EV_REMOTE_NAME: {
-                DBG_PRINT("hci_send_req: HCI_EV_REMOTE_NAME: event 0x%X (equal %d), exp_event 0x%X, r-len %d/%d",
-                          hdr->evt, exp_event, (hdr->evt == exp_event), response_len, len);
-
-                if (hdr->evt != exp_event) {
-                    continue; // next packet
-                }
-
-                const hci_ev_remote_name *rn = static_cast<const hci_ev_remote_name *>(static_cast<const void *>( ptr ));
-                const hci_cp_remote_name_req *cp = static_cast<const hci_cp_remote_name_req *>(command);
-
-                if ( rn->bdaddr != cp->bdaddr ) {
-                    DBG_PRINT("hci_send_req: HCI_EV_REMOTE_NAME: address mismatch: cmd %s != req %s",
-                              cp->bdaddr.toString().c_str(), rn->bdaddr.toString().c_str());
-                    continue; // next packet
-                }
-
-                const int rlen = MIN(len, response_len);
-                memcpy(response, ptr, rlen);
-                DBG_PRINT("hci_send_req: HCI_EV_REMOTE_NAME: copied %d bytes: %s",
-                        rlen, bytesHexString((uint8_t*)ptr, 0, rlen, false /* lsbFirst */, true /* leading0X */).c_str());
-                goto done;
-		    }
 
 		case HCI_EV_LE_META: {
                 const hci_ev_le_meta *me = static_cast<const hci_ev_le_meta *>(static_cast<const void *>( ptr ));
diff --git a/src/direct_bt/L2CAPComm.cpp b/src/direct_bt/L2CAPComm.cpp
index b58ee536..c36bedb8 100644
--- a/src/direct_bt/L2CAPComm.cpp
+++ b/src/direct_bt/L2CAPComm.cpp
@@ -192,7 +192,10 @@ bool L2CAPComm::disconnect() {
     if( 0 != _tid_connect ) {
         pthread_t tid_self = pthread_self();
         if( tid_self != _tid_connect ) {
-            pthread_kill(_tid_connect, SIGALRM);
+            int kerr;
+            if( 0 != ( kerr = pthread_kill(_tid_connect, SIGALRM) ) ) {
+                ERR_PRINT("L2CAP::disconnect: pthread_kill %p FAILED: %d", (void*)_tid_connect, kerr);
+            }
         }
     }