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)

3 files changed, 72 insertions, 12 deletions

diff --git a/src/bluetooth/osx/osxbtdeviceinquiry.mm b/src/bluetooth/osx/osxbtdeviceinquiry.mm
index 6048a5c4..719e2060 100644
--- a/src/bluetooth/osx/osxbtdeviceinquiry.mm
+++ b/src/bluetooth/osx/osxbtdeviceinquiry.mm
@@ -112,11 +112,14 @@ const uint8_t IOBlueoothInquiryLengthS = 15;
 
     m_active = true;
     [m_inquiry clearFoundDevices];
+
+    qCDebug(QT_BT_OSX) << "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_OSX) << "failed with IOKit error code:" << result;
+        qCWarning(QT_BT_OSX) << "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_OSX, "Manually interrupting IOBluetoothDeviceInquiry");
+            qCDebug(QT_BT_OSX) << "Found devices:" << [m_inquiry foundDevices];
             [self stop];
         });
 
@@ -150,6 +154,8 @@ const uint8_t IOBlueoothInquiryLengthS = 15;
 - (void)deviceInquiryComplete:(IOBluetoothDeviceInquiry *)sender
         error:(IOReturn)error aborted:(BOOL)aborted
 {
+    qCDebug(QT_BT_OSX) << "deviceInquiryComplete, error:" << error
+                          << "user-stopped:" << aborted;
     if (!m_active)
         return;
 
@@ -176,6 +182,7 @@ const uint8_t IOBlueoothInquiryLengthS = 15;
 - (void)deviceInquiryDeviceFound:(IOBluetoothDeviceInquiry *)sender
         device:(IOBluetoothDevice *)device
 {
+    qCDebug(QT_BT_OSX) << "deviceInquiryDeviceFound:" << [device nameOrAddress];
     if (sender != m_inquiry) // Can never happen in the current version.
         return;
 
diff --git a/src/bluetooth/osx/osxbtsdpinquiry.mm b/src/bluetooth/osx/osxbtsdpinquiry.mm
index 481a077b..13d22745 100644
--- a/src/bluetooth/osx/osxbtsdpinquiry.mm
+++ b/src/bluetooth/osx/osxbtsdpinquiry.mm
@@ -268,6 +268,13 @@ using namespace OSXBluetooth;
     Q_ASSERT(device);
 
     Q_ASSERT_X(delegate, Q_FUNC_INFO, "invalid delegate (null)");
+    qCDebug(QT_BT_OSX) << "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 release];
@@ -280,6 +287,7 @@ using namespace OSXBluetooth;
 {
     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_OSX) << "Starting and SDP inquiry for address:" << address;
 
     QT_BT_MAC_AUTORELEASEPOOL;
 
@@ -315,6 +323,8 @@ using namespace OSXBluetooth;
     ObjCScopedPointer<IOBluetoothDevice> oldDevice(device);
     device = newDevice.data();
 
+    qCDebug(QT_BT_OSX) << "Device" << [device nameOrAddress] << "connected:"
+                          << bool([device isConnected]) << "paired:" << bool([device isPaired]);
     IOReturn result = kIOReturnSuccess;
 
     if (QOperatingSystemVersion::current() > QOperatingSystemVersion::MacOSBigSur) {
@@ -325,22 +335,44 @@ using namespace OSXBluetooth;
         // - 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_OSX) << "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_OSX) << "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_OSX) << "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];
 
         if (result != kIOReturnSuccess) {
             qCCritical(QT_BT_OSX, "failed to start an SDP query");
-            connectionWatchdog.reset();
             device = oldDevice.take();
         } else {
             newDevice.take();
@@ -368,12 +400,17 @@ using namespace OSXBluetooth;
 
 - (void)connectionComplete:(IOBluetoothDevice *)aDevice status:(IOReturn)status
 {
+    qCDebug(QT_BT_OSX) << "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];
@@ -388,7 +425,7 @@ using namespace OSXBluetooth;
 
 - (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 release];
@@ -399,6 +436,8 @@ using namespace OSXBluetooth;
 
 - (void)sdpQueryComplete:(IOBluetoothDevice *)aDevice status:(IOReturn)status
 {
+    qCDebug(QT_BT_OSX) << "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.
@@ -409,6 +448,15 @@ using namespace OSXBluetooth;
 
     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_OSX) << "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_osx.mm b/src/bluetooth/qbluetoothservicediscoveryagent_osx.mm
index 8469dd59..49085724 100644
--- a/src/bluetooth/qbluetoothservicediscoveryagent_osx.mm
+++ b/src/bluetooth/qbluetoothservicediscoveryagent_osx.mm
@@ -149,15 +149,20 @@ void QBluetoothServiceDiscoveryAgentPrivate::SDPInquiryFinished(void *generic)
     QT_BT_MAC_AUTORELEASEPOOL;
 
     NSArray *const records = device.services;
+    qCDebug(QT_BT_OSX) << "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_OSX) << "Processing service" << [record getServiceName];
         serviceInfo.setDevice(discoveredDevices.at(0));
         OSXBluetooth::extract_service_record(record, serviceInfo);
 
-        if (!serviceInfo.isValid())
+        if (!serviceInfo.isValid()) {
+            qCDebug(QT_BT_OSX) << "Discarding invalid service";
             continue;
+        }
 
         if (QOperatingSystemVersion::current() > QOperatingSystemVersion::MacOSBigSur
             && uuidFilter.size()) {