[bluetooth.bluez] Improve stability of BlueZ adapter and align with interface

Wrong method implementation/assumption
--------------------------------------

`BluetoothDevice#connect` is documented as: "[...] Connects to a device. This is
an asynchronous method. [...]" and there is a companion method
`BluetoothDevice#awaitConnection`. While documentation on the latter method is
missing, it only makes sense if `connect` is indeed implemented asynchronously
and `awaitConnection` allows to issue a bounded wait for the connection to be
established.

There are two issues:

- ConnectedBluetoothHandler assumes that BluetoothDevice#connect indeed connects
  and returns `true` on successful connection in the `reconnectJob`. The problem
  is that `true` only means, that the connection process started. This is
  rectified by issuing a `connect` called followd by an `awaitConnection` call.
  The latter assumes that connection is established after not more than 30s.

- `BlueZBluetoothDevice#connect` directly calls into the bluez adapter `Connect`
  method which is blocking. To work around this the call is dispatched into
  an asynchronous call and parallel invocation is prevented using an
  AtomicBoolean as lock/indicator.

Too early BlueZ GATT characteristic interaction
-----------------------------------------------

The BlueZ API does not make the characteristics available to clients until
service discovery is done. Service discovery is automatically started after
a connection is established. The methods interacting with bluetooth GATT
characteristics have to wait until discovery is done and can only then attempt
to read/write the characteristics.

getDBusBlueZCharacteristicByUUID is thus modified to wait for discovery to
finish.

Most code paths are already prepared for an asynchronous invocation and this
discovery becomes part of that chain.


Timeouts
--------

While working with Govee Bluetooth LE devices it was noted, that these devices
take a long time to connect. The observed numbers were:

| Scanning | Discovery |
| -------- | --------- |
|    12,5s |      0,3s |
|    16,2s |      0,8s |
|    14,9s |      0,3s |
|    15,1s |      0,3s |
|     8,0s |      0,8s |
|    11,1s |      0,3s |
|    14,6s |      0,3s |
|    28,0s |      0,3s |
|     4,6s |      0,3s |
|    17,3s |      0,3s |
|    19,5s |      0,3s |
|    15,9s |      0,3s |
|     4,0s |      0,8s |
|    13,6s |      0,3s |
|    19,2s |      0,3s |

This causes problems as that might exceed the default limit of 20s dbus-java
sets for replies for dbus calls.

The timeouts for connection and discovery were thus bumped to 30s to account for
slow devices.

The call timeout for dbus-java was bumped to 60s. It is assumed, that the
dbus connection can be assumed to be stable in general and thus calls that take
long are not broken at the connection level, but are indeed just slow.


Signed-off-by: Matthias Bläsing <mblaesing@doppel-helix.eu>

Author: matthiasblaesing

bundles/org.openhab.binding.bluetooth.bluez/src/main/java/org/openhab/binding/bluetooth/bluez/internal/BlueZBluetoothDevice.java

@@ -17,12 +17,14 @@
 import java.util.Objects;
 import java.util.UUID;
 import java.util.concurrent.CompletableFuture;
+import java.util.concurrent.ExecutionException;
 import java.util.concurrent.ScheduledExecutorService;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicInteger;
 
 import org.eclipse.jdt.annotation.NonNullByDefault;
 import org.eclipse.jdt.annotation.Nullable;
-import org.freedesktop.dbus.errors.NoReply;
 import org.freedesktop.dbus.errors.UnknownObject;
 import org.freedesktop.dbus.exceptions.DBusException;
 import org.freedesktop.dbus.exceptions.DBusExecutionException;
@@ -72,6 +74,8 @@ public class BlueZBluetoothDevice extends BaseBluetoothDevice implements BlueZEv
 
     private final ScheduledExecutorService scheduler = ThreadPoolManager.getScheduledPool("bluetooth");
 
+    private final AtomicBoolean connectionStartRunning = new AtomicBoolean();
+
     // Device from native lib
     private @Nullable BluetoothDevice device = null;
 
@@ -170,6 +174,7 @@ public void dispose() {
     }
 
     private void setConnectionState(ConnectionState state) {
+        logger.debug("Update connection state for {} to {}", address, state);
         if (this.connectionState != state) {
             this.connectionState = state;
             notifyListeners(BluetoothEventType.CONNECTION_STATE, new BluetoothConnectionStatusNotification(state));
@@ -207,42 +212,47 @@ synchronized void resetForRemoval() {
 
     @Override
     public boolean connect() {
-        logger.debug("Connect({})", device);
-
         BluetoothDevice dev = device;
-        if (dev != null) {
-            if (Boolean.FALSE.equals(dev.isConnected())) {
-                // BlueZ Device.Connect() is unreliable while the adapter is actively discovering
-                // (the call blocks / does not complete). Pause discovery first; the bridge's periodic
-                // refresh job resumes it shortly after.
-                bridgeHandler.stopDiscovery();
-                try {
+
+        if (dev == null) {
+            return false;
+        }
+
+        logger.debug("Connect({})", dev);
+
+        if (Boolean.FALSE.equals(dev.isConnected())) {
+            if (connectionStartRunning.compareAndSet(false, true)) {
+                CompletableFuture.runAsync(() -> {
+                    setConnectionState(ConnectionState.CONNECTING);
+                    // BlueZ Device.Connect() is unreliable while the adapter is actively discovering
+                    // (the call blocks / does not complete). Pause discovery first; the bridge's periodic
+                    // refresh job resumes it shortly after.
+                    bridgeHandler.stopDiscovery();
+                    // This method does not block at most until the dbus-java
+                    // method timeout is reached.
                     boolean ret = dev.connect();
                     logger.debug("Connect result: {}", ret);
-                    return ret;
-                } catch (NoReply e) {
-                    // Have to double check because sometimes, exception but still worked
-                    logger.debug("Got a timeout - but sometimes happen. Is Connected ? {}", dev.isConnected());
-                    if (Boolean.FALSE.equals(dev.isConnected())) {
-                        notifyListeners(BluetoothEventType.CONNECTION_STATE,
-                                new BluetoothConnectionStatusNotification(ConnectionState.DISCONNECTED));
-                        return false;
-                    } else {
-                        return true;
+                    ConnectionState cs1 = ret ? ConnectionState.CONNECTED : ConnectionState.DISCONNECTED;
+                    logger.debug("Updating connection state after connect: {}", cs1);
+                    setConnectionState(cs1);
+                }, scheduler).handle((voidResult, th) -> {
+                    if (th != null) {
+                        logger.debug("Failed to connect", th);
+                        setConnectionState(ConnectionState.DISCONNECTED);
                     }
-                } catch (DBusExecutionException e) {
-                    // Catch "software caused connection abort"
-                    return false;
-                } catch (Exception e) {
-                    logger.warn("error occurred while trying to connect", e);
-                }
+                    connectionStartRunning.set(false);
+                    return null;
+                });
             } else {
-                logger.debug("Device was already connected");
-                // we might be stuck in another state atm so we need to trigger a connected in this case
-                setConnectionState(ConnectionState.CONNECTED);
-                return true;
+                logger.debug("Connection already in progress for {}", address);
             }
+            return true;
+        } else {
+            logger.debug("Device was already connected");
+            // we might be stuck in another state atm so we need to trigger a connected in this case
+            setConnectionState(ConnectionState.CONNECTED);
         }
+
         return false;
     }
 
@@ -283,19 +293,29 @@ private List<BluetoothGattService> getGattServicesRefreshed(BluetoothDevice dev)
         return services;
     }
 
-    private @Nullable BluetoothGattCharacteristic getDBusBlueZCharacteristicByUUID(String uuid) {
+    private @Nullable CompletableFuture<BluetoothGattCharacteristic> getDBusBlueZCharacteristicByUUID(String uuid) {
         BluetoothDevice dev = device;
         if (dev == null) {
             return null;
         }
-        for (BluetoothGattService service : getGattServicesRefreshed(dev)) {
-            for (BluetoothGattCharacteristic characteristic : service.getGattCharacteristics()) {
-                if (characteristic != null && uuid.equalsIgnoreCase(characteristic.getUuid())) {
-                    return characteristic;
+        AtomicInteger atomicInteger = new AtomicInteger();
+        return RetryFuture.callWithRetry(() -> {
+            if (Boolean.TRUE.equals(dev.isServicesResolved())) {
+                for (BluetoothGattService service : getGattServicesRefreshed(dev)) {
+                    for (BluetoothGattCharacteristic characteristic : service.getGattCharacteristics()) {
+                        if (characteristic != null && uuid.equalsIgnoreCase(characteristic.getUuid())) {
+                            return characteristic;
+                        }
+                    }
                 }
             }
-        }
-        return null;
+
+            if (atomicInteger.incrementAndGet() < 100) { // 100 iterations 50ms each => 5s
+                throw new RetryException(50, TimeUnit.MILLISECONDS);
+            }
+
+            throw new IllegalStateException("Characteristic " + uuid + " is missing on device");
+        }, scheduler);
     }
 
     private @Nullable BluetoothGattCharacteristic getDBusBlueZCharacteristicByDBusPath(String dBusPath) {
@@ -323,30 +343,25 @@ private List<BluetoothGattService> getGattServicesRefreshed(BluetoothDevice dev)
                     .failedFuture(new IllegalStateException("DBusBlueZ device is not set or not connected"));
         }
 
-        BluetoothGattCharacteristic c = getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString());
-        if (c == null) {
-            logger.warn("Characteristic '{}' is missing on device '{}'.", characteristic.getUuid(), address);
-            return CompletableFuture.failedFuture(
-                    new IllegalStateException("Characteristic " + characteristic.getUuid() + " is missing on device"));
-        }
-
-        return RetryFuture.callWithRetry(() -> {
-            try {
-                c.startNotify();
-            } catch (DBusException e) {
-                String exceptionMessage = e.getMessage();
-                if (exceptionMessage != null && exceptionMessage.contains("Already notifying")) {
+        return getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString())
+                .thenCompose(c -> RetryFuture.callWithRetry(() -> {
+                    try {
+                        c.startNotify();
+                    } catch (DBusExecutionException e) {
+                        String exceptionMessage = e.getMessage();
+                        if (exceptionMessage != null && exceptionMessage.contains("Already notifying")) {
+                            return null;
+                        } else if (exceptionMessage != null && exceptionMessage.contains("In Progress")) {
+                            // let's retry in half a second
+                            throw new RetryException(500, TimeUnit.MILLISECONDS);
+                        } else {
+                            logger.warn("Exception occurred while activating notifications on '{}'", address, e);
+                            throw e;
+                        }
+                    }
+                    ;
                     return null;
-                } else if (exceptionMessage != null && exceptionMessage.contains("In Progress")) {
-                    // let's retry in half a second
-                    throw new RetryException(500, TimeUnit.MILLISECONDS);
-                } else {
-                    logger.warn("Exception occurred while activating notifications on '{}'", address, e);
-                    throw e;
-                }
-            }
-            return null;
-        }, scheduler);
+                }, scheduler));
     }
 
     @Override
@@ -359,23 +374,17 @@ private List<BluetoothGattService> getGattServicesRefreshed(BluetoothDevice dev)
                     .failedFuture(new IllegalStateException("DBusBlueZ device is not set or not connected"));
         }
 
-        BluetoothGattCharacteristic c = getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString());
-        if (c == null) {
-            logger.warn("Characteristic '{}' is missing on device '{}'.", characteristic.getUuid(), address);
-            return CompletableFuture.failedFuture(
-                    new IllegalStateException("Characteristic " + characteristic.getUuid() + " is missing on device"));
-        }
-
-        return RetryFuture.callWithRetry(() -> {
-            try {
-                c.writeValue(value, null);
-                return null;
-            } catch (DBusException e) {
-                logger.debug("Exception occurred when trying to write characteristic '{}': {}",
-                        characteristic.getUuid(), e.getMessage());
-                throw e;
-            }
-        }, scheduler);
+        return getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString())
+                .thenCompose(c -> RetryFuture.callWithRetry(() -> {
+                    try {
+                        c.writeValue(value, null);
+                        return null;
+                    } catch (DBusException e) {
+                        logger.debug("Exception occurred when trying to write characteristic '{}': {}",
+                                characteristic.getUuid(), e.getMessage());
+                        throw e;
+                    }
+                }, scheduler));
     }
 
     @Override
@@ -385,6 +394,7 @@ public void onDBusBlueZEvent(BlueZEvent event) {
 
     @Override
     public void onServicesResolved(ServicesResolvedEvent event) {
+        logger.debug("onServicesResolved: {}", event.isResolved());
         if (event.isResolved()) {
             // Populate our service/characteristic list from the now-resolved GATT and notify
             // listeners. BlueZ can deliver ServicesResolved=true while our own supportedServices list
@@ -461,9 +471,7 @@ public void onRssiUpdate(RssiEvent event) {
 
     @Override
     public void onConnectedStatusUpdate(ConnectedEvent event) {
-        this.connectionState = event.isConnected() ? ConnectionState.CONNECTED : ConnectionState.DISCONNECTED;
-        notifyListeners(BluetoothEventType.CONNECTION_STATE,
-                new BluetoothConnectionStatusNotification(connectionState));
+        setConnectionState(event.isConnected() ? ConnectionState.CONNECTED : ConnectionState.DISCONNECTED);
     }
 
     @Override
@@ -562,33 +570,32 @@ public CompletableFuture<byte[]> readCharacteristic(BluetoothCharacteristic char
                     .failedFuture(new IllegalStateException("DBusBlueZ device is not set or not connected"));
         }
 
-        BluetoothGattCharacteristic c = getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString());
-        if (c == null) {
-            logger.warn("Characteristic '{}' is missing on device '{}'.", characteristic.getUuid(), address);
-            return CompletableFuture.failedFuture(
-                    new IllegalStateException("Characteristic " + characteristic.getUuid() + " is missing on device"));
-        }
-
-        return RetryFuture.callWithRetry(() -> {
-            try {
-                return c.readValue(null);
-            } catch (DBusException | DBusExecutionException e) {
-                // DBusExecutionException is thrown if the value cannot be read
-                logger.debug("Exception occurred when trying to read characteristic '{}': {}", characteristic.getUuid(),
-                        e.getMessage());
-                throw e;
-            }
-        }, scheduler);
+        return getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString())
+                .thenCompose(c -> RetryFuture.callWithRetry(() -> {
+                    try {
+                        return c.readValue(null);
+                    } catch (DBusException | DBusExecutionException e) {
+                        // DBusExecutionException is thrown if the value cannot be read
+                        logger.debug("Exception occurred when trying to read characteristic '{}': {}",
+                                characteristic.getUuid(), e.getMessage());
+                        throw e;
+                    }
+                }, scheduler));
     }
 
     @Override
     public boolean isNotifying(BluetoothCharacteristic characteristic) {
-        BluetoothGattCharacteristic c = getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString());
-        if (c != null) {
-            Boolean isNotifying = c.isNotifying();
-            return Objects.requireNonNullElse(isNotifying, false);
-        } else {
-            logger.warn("Characteristic '{}' is missing on device '{}'.", characteristic.getUuid(), address);
+        try {
+            BluetoothGattCharacteristic c = getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString()).get();
+            if (c != null) {
+                Boolean isNotifying = c.isNotifying();
+                return Objects.requireNonNullElse(isNotifying, false);
+            } else {
+                logger.warn("Characteristic '{}' is missing on device '{}'.", characteristic.getUuid(), address);
+                return false;
+            }
+        } catch (InterruptedException | ExecutionException ex) {
+            logger.warn("Fetchig characteristic '{}' for device '{}'.", characteristic.getUuid(), address, ex);
             return false;
         }
     }
@@ -597,33 +604,32 @@ public boolean isNotifying(BluetoothCharacteristic characteristic) {
     public CompletableFuture<@Nullable Void> disableNotifications(BluetoothCharacteristic characteristic) {
         BluetoothDevice dev = device;
         if (dev == null || Boolean.FALSE.equals(dev.isConnected())) {
-            return CompletableFuture
-                    .failedFuture(new IllegalStateException("DBusBlueZ device is not set or not connected"));
-        }
-        BluetoothGattCharacteristic c = getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString());
-        if (c == null) {
-            logger.warn("Characteristic '{}' is missing on device '{}'.", characteristic.getUuid(), address);
-            return CompletableFuture.failedFuture(
-                    new IllegalStateException("Characteristic " + characteristic.getUuid() + " is missing on device"));
+            String message;
+            if (dev == null) {
+                message = "DBusBlueZ device is not set";
+            } else {
+                message = "DBusBlueZ device is not not connected";
+            }
+            return CompletableFuture.failedFuture(new IllegalStateException(message));
         }
-
-        return RetryFuture.callWithRetry(() -> {
-            try {
-                c.stopNotify();
-            } catch (DBusException e) {
-                String exceptionMessage = e.getMessage();
-                if (exceptionMessage != null && exceptionMessage.contains("Already notifying")) {
+        return getDBusBlueZCharacteristicByUUID(characteristic.getUuid().toString())
+                .thenCompose(c -> RetryFuture.callWithRetry(() -> {
+                    try {
+                        c.stopNotify();
+                    } catch (DBusExecutionException e) {
+                        String exceptionMessage = e.getMessage();
+                        if (exceptionMessage != null && exceptionMessage.contains("Already notifying")) {
+                            return null;
+                        } else if (exceptionMessage != null && exceptionMessage.contains("In Progress")) {
+                            // let's retry in half a second
+                            throw new RetryException(500, TimeUnit.MILLISECONDS);
+                        } else {
+                            logger.warn("Exception occurred while deactivating notifications on '{}'", address, e);
+                            throw e;
+                        }
+                    }
                     return null;
-                } else if (exceptionMessage != null && exceptionMessage.contains("In Progress")) {
-                    // let's retry in half a second
-                    throw new RetryException(500, TimeUnit.MILLISECONDS);
-                } else {
-                    logger.warn("Exception occurred while deactivating notifications on '{}'", address, e);
-                    throw e;
-                }
-            }
-            return null;
-        }, scheduler);
+                }, scheduler));
     }
 
     @Override

bundles/org.openhab.binding.bluetooth.bluez/src/main/java/org/openhab/binding/bluetooth/bluez/internal/BlueZBridgeHandler.java

@@ -27,6 +27,7 @@
 import org.eclipse.jdt.annotation.NonNullByDefault;
 import org.eclipse.jdt.annotation.Nullable;
 import org.freedesktop.dbus.exceptions.DBusExecutionException;
+import org.freedesktop.dbus.messages.MethodCall;
 import org.freedesktop.dbus.types.Variant;
 import org.openhab.binding.bluetooth.AbstractBluetoothBridgeHandler;
 import org.openhab.binding.bluetooth.BluetoothAddress;
@@ -61,6 +62,10 @@
 public class BlueZBridgeHandler extends AbstractBluetoothBridgeHandler<BlueZBluetoothDevice>
         implements BlueZEventListener {
 
+    static {
+        MethodCall.setDefaultTimeout(60_000);
+    }
+
     private final Logger logger = LoggerFactory.getLogger(BlueZBridgeHandler.class);
 
     // ADAPTER from BlueZ-DBus Library