Improve bluetooth service discovery on macOS Monterey

The original problem is that on macOS Monterey the service discovery,
and subsequent usage of the services, is unreliable. This commit
improves the situation a bit by checking the connectivity status
of the device instead of relying on IOBluetooth callbacks which
quite often don't arrive.

Also there was a crash due to stray callbacks from IOBluetooth.
These seem to cease when we now close the connection we have
established for SDP inquiry purposes. The crash happened especially
if the remote device got paired during the service scan.

In addition this commit introduces more event logging which helps
when debugging these issues.

Fixes: QTBUG-100303
Change-Id: Id063401390b141cff412cbb47d20d441cc394d3f
Reviewed-by: Timur Pocheptsov <timur.pocheptsov@qt.io>
(cherry picked from commit 2e09bf6c57c8cb0c1069b562ab2451ec8b68c27a)
Reviewed-by: Qt Cherry-pick Bot <cherrypick_bot@qt-project.org>

3 files changed, 72 insertions, 12 deletions

diff --git a/src/bluetooth/darwin/btdeviceinquiry.mm b/src/bluetooth/darwin/btdeviceinquiry.mm
index 2d042fd4..356b18e6 100644
--- a/src/bluetooth/darwin/btdeviceinquiry.mm
+++ b/src/bluetooth/darwin/btdeviceinquiry.mm
@@ -112,11 +112,14 @@ const uint8_t IOBlueoothInquiryLengthS = 15;
 
     m_active = true;
     [m_inquiry clearFoundDevices];
+
+    qCDebug(QT_BT_DARWIN) << "Starting device inquiry with"
+                          << IOBlueoothInquiryLengthS << "second timeout limit.";
     const IOReturn result = [m_inquiry start];
     if (result != kIOReturnSuccess) {
         // QtBluetooth will probably convert an error into UnknownError,
         // losing the actual information.
-        qCWarning(QT_BT_DARWIN) << "failed with IOKit error code:" << result;
+        qCWarning(QT_BT_DARWIN) << "device inquiry start failed with IOKit error code:" << result;
         m_active = false;
     } else {
         // Docs say it's 10 s. by default, we set it to 15 s. (see -initWithDelegate:),
@@ -124,6 +127,7 @@ const uint8_t IOBlueoothInquiryLengthS = 15;
         watchDog.reset(new QTimer);
         watchDog->connect(watchDog.get(), &QTimer::timeout, watchDog.get(), [self]{
             qCWarning(QT_BT_DARWIN, "Manually interrupting IOBluetoothDeviceInquiry");
+            qCDebug(QT_BT_DARWIN) << "Found devices:" << [m_inquiry foundDevices];
             [self stop];
         });
 
@@ -149,6 +153,8 @@ const uint8_t IOBlueoothInquiryLengthS = 15;
 - (void)deviceInquiryComplete:(IOBluetoothDeviceInquiry *)sender
         error:(IOReturn)error aborted:(BOOL)aborted
 {
+    qCDebug(QT_BT_DARWIN) << "deviceInquiryComplete, error:" << error
+                          << "user-stopped:" << aborted;
     if (!m_active)
         return;
 
@@ -175,6 +181,7 @@ const uint8_t IOBlueoothInquiryLengthS = 15;
 - (void)deviceInquiryDeviceFound:(IOBluetoothDeviceInquiry *)sender
         device:(IOBluetoothDevice *)device
 {
+    qCDebug(QT_BT_DARWIN) << "deviceInquiryDeviceFound:" << [device nameOrAddress];
     if (sender != m_inquiry) // Can never happen in the current version.
         return;
 
diff --git a/src/bluetooth/darwin/btsdpinquiry.mm b/src/bluetooth/darwin/btsdpinquiry.mm
index 025f25bb..b5497b65 100644
--- a/src/bluetooth/darwin/btsdpinquiry.mm
+++ b/src/bluetooth/darwin/btsdpinquiry.mm
@@ -267,6 +267,13 @@ using namespace DarwinBluetooth;
     Q_ASSERT(device.get());
 
     Q_ASSERT_X(delegate, Q_FUNC_INFO, "invalid delegate (null)");
+    qCDebug(QT_BT_DARWIN) << "couldn't connect to device" << [device nameOrAddress]
+                          << ", ending SDP inquiry.";
+
+    // Stop the watchdog and close the connection as otherwise there could be
+    // later "connectionComplete" callbacks
+    connectionWatchdog->stop();
+    [device closeConnection];
 
     delegate->SDPInquiryError(device, kIOReturnTimeout);
     device.reset();
@@ -278,6 +285,7 @@ using namespace DarwinBluetooth;
 {
     Q_ASSERT_X(!isActive, Q_FUNC_INFO, "SDP query in progress");
     Q_ASSERT_X(!address.isNull(), Q_FUNC_INFO, "invalid target device address");
+    qCDebug(QT_BT_DARWIN) << "Starting and SDP inquiry for address:" << address;
 
     QT_BT_MAC_AUTORELEASEPOOL;
 
@@ -309,6 +317,8 @@ using namespace DarwinBluetooth;
         qCCritical(QT_BT_DARWIN) << "failed to create an IOBluetoothDevice object";
         return kIOReturnError;
     }
+    qCDebug(QT_BT_DARWIN) << "Device" << [device nameOrAddress] << "connected:"
+                          << bool([device isConnected]) << "paired:" << bool([device isPaired]);
 
     IOReturn result = kIOReturnSuccess;
 
@@ -320,15 +330,38 @@ using namespace DarwinBluetooth;
         // - a version with UUID filters simply does nothing except it immediately
         //   returns kIOReturnSuccess.
 
+        // If the device was not yet connected, connect it first
         if (![device isConnected]) {
+            qCDebug(QT_BT_DARWIN) << "Device" << [device nameOrAddress]
+                                  << "is not connected, connecting it first";
             result = [device openConnection:self];
-            connectionWatchdog.reset(new QTimer);
-            connectionWatchdog->setSingleShot(true);
-            QObject::connect(connectionWatchdog.get(), &QTimer::timeout,
-                             connectionWatchdog.get(),
-                             [self]{[self interruptSDPQuery];});
-            connectionWatchdog->start(basebandConnectTimeoutMS);
-        }
+            // The connection may succeed immediately. But if it didn't, start a connection timer
+            // which has two guardian roles:
+            // 1. Guard against connect attempt taking too long time
+            // 2. Sometimes on Monterey the callback indicating "connection completion" is
+            //    not received even though the connection has in fact succeeded
+            if (![device isConnected]) {
+                qCDebug(QT_BT_DARWIN) << "Starting connection monitor for device"
+                                      << [device nameOrAddress] << "with timeout limit of"
+                                      << basebandConnectTimeoutMS/1000 << "seconds.";
+                connectionWatchdog.reset(new QTimer);
+                connectionWatchdog->setSingleShot(false);
+                QObject::connect(connectionWatchdog.get(), &QTimer::timeout,
+                                 connectionWatchdog.get(),
+                                 [self] () {
+                    qCDebug(QT_BT_DARWIN) << "Connection monitor timeout for device:"
+                                          << [device nameOrAddress]
+                                          << ", connected:" << bool([device isConnected]);
+                    // Device can sometimes get properly connected without IOBluetooth
+                    // calling the connectionComplete callback, so we check the status here
+                    if ([device isConnected])
+                        [self connectionComplete:device status:kIOReturnSuccess];
+                    else
+                        [self interruptSDPQuery];
+                });
+                connectionWatchdog->start(basebandConnectTimeoutMS);
+            }
+         }
 
         if ([device isConnected])
             result = [device performSDPQuery:self];
@@ -336,7 +369,6 @@ using namespace DarwinBluetooth;
         if (result != kIOReturnSuccess) {
             qCCritical(QT_BT_DARWIN, "failed to start an SDP query");
             device.reset();
-            connectionWatchdog.reset();
         } else {
             isActive = true;
         }
@@ -361,12 +393,17 @@ using namespace DarwinBluetooth;
 
 - (void)connectionComplete:(IOBluetoothDevice *)aDevice status:(IOReturn)status
 {
+    qCDebug(QT_BT_DARWIN) << "connectionComplete for device" << [aDevice nameOrAddress]
+                          << "with status:" << status;
     if (aDevice != device) {
         // Connection was previously cancelled, probably, due to the timeout.
         return;
     }
 
-    connectionWatchdog.reset();
+    // The connectionComplete may be invoked by either the IOBluetooth callback or our
+    // connection watchdog. In either case stop the watchdog if it exists
+    if (connectionWatchdog)
+        connectionWatchdog->stop();
 
     if (status == kIOReturnSuccess)
         status = [aDevice performSDPQuery:self];
@@ -381,7 +418,7 @@ using namespace DarwinBluetooth;
 
 - (void)stopSDPQuery
 {
-    // There is no API to stop it SDP on deice, but there is a 'stop'
+    // There is no API to stop it SDP on device, but there is a 'stop'
     // member-function in Qt and after it's called sdpQueryComplete
     // must be somehow ignored (device != aDevice in a callback).
     device.reset();
@@ -391,6 +428,8 @@ using namespace DarwinBluetooth;
 
 - (void)sdpQueryComplete:(IOBluetoothDevice *)aDevice status:(IOReturn)status
 {
+    qCDebug(QT_BT_DARWIN) << "sdpQueryComplete for device:" << [aDevice nameOrAddress]
+                          << "with status:" << status;
     // Can happen - there is no legal way to cancel an SDP query,
     // after the 'reset' device can never be
     // the same as the cancelled one.
@@ -401,6 +440,15 @@ using namespace DarwinBluetooth;
 
     isActive = false;
 
+    // If we used the manual connection establishment, close the
+    // connection here. Otherwise the IOBluetooth may call stray
+    // connectionComplete or sdpQueryCompletes
+    if (connectionWatchdog) {
+        qCDebug(QT_BT_DARWIN) << "Closing the connection established for SDP inquiry.";
+        connectionWatchdog.reset();
+        [device closeConnection];
+    }
+
     if (status != kIOReturnSuccess)
         delegate->SDPInquiryError(aDevice, status);
     else
diff --git a/src/bluetooth/qbluetoothservicediscoveryagent_macos.mm b/src/bluetooth/qbluetoothservicediscoveryagent_macos.mm
index f5eff9f4..8aaf3b51 100644
--- a/src/bluetooth/qbluetoothservicediscoveryagent_macos.mm
+++ b/src/bluetooth/qbluetoothservicediscoveryagent_macos.mm
@@ -150,15 +150,20 @@ void QBluetoothServiceDiscoveryAgentPrivate::SDPInquiryFinished(void *generic)
     QT_BT_MAC_AUTORELEASEPOOL;
 
     NSArray *const records = device.services;
+    qCDebug(QT_BT_DARWIN) << "SDP finished for device" << [device nameOrAddress]
+                          << ", services found:" << [records count];
     for (IOBluetoothSDPServiceRecord *record in records) {
         QBluetoothServiceInfo serviceInfo;
         Q_ASSERT_X(discoveredDevices.size() >= 1, Q_FUNC_INFO, "invalid number of devices");
 
+        qCDebug(QT_BT_DARWIN) << "Processing service" << [record getServiceName];
         serviceInfo.setDevice(discoveredDevices.at(0));
         DarwinBluetooth::extract_service_record(record, serviceInfo);
 
-        if (!serviceInfo.isValid())
+        if (!serviceInfo.isValid()) {
+            qCDebug(QT_BT_DARWIN) << "Discarding invalid service";
             continue;
+        }
 
         if (QOperatingSystemVersion::current() > QOperatingSystemVersion::MacOSBigSur
             && uuidFilter.size()) {