ble connection timeouts

[ojg78]

Very useful, thank you. Is it just the nature of ble that commands need to be issued several times before they are acknowledged by the Pokit Pro? Seems like it needs a very recent connection to have happened to accept further commands.

PS C:\Users\xxxxx\Downloads\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable> .\dokit -d orange logger-fetch
dokit.cli.command: Looking for device "orange"...
qt.bluetooth.windows: Could not await characteristic read
dokit.cli.command: Bluetooth controller error: QLowEnergyController::ConnectionError
PS C:\Users\xxxxx\Downloads\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable> .\dokit -d orange logger-fetch
dokit.cli.command: Looking for device "orange"...
dokit.cli.command: Fetching logger samples...
dokit.cli.command: Fetching 48 logger samples..

[pcolby]

Hi @ojg78, thanks for the feedback. Its a good question, and I'm not sure of the answer, since Qt handles BLE connections a bit differently on each platform. So while I don't see that timeout on any of my Pokit devices, I'm most often testing on Linux.

You could try raising the timeout (eg to 3 minutes), and enabling debug output, like:

dokit -d orange logger-fetch --timeout 180s --debug

Let us know if that helps, or what the debug output shows. Thanks!

[ojg78]

With the 180 second timeout the same behaviour occurs, issue the command once and get an error then immediately issue the command again to get a successful response. The 180 second timeout option returns the error without delay. Debug below.

PS C:\Users\xxxxx\Downloads\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable> .\dokit -d orange logger-fetch --timeout 180s --debug
     0.000 16168 debug dokit.cli.main: Dokit 0.5.3+1375.win.x86-64.msvc.qt-6.8.0
     0.000 16168 debug dokit.cli.main: Qt 6.8.0 compile-time
     0.000 16168 debug dokit.cli.main: Qt 6.8.0 runtime
     0.000 16168 debug dokit.cli.main: App translations: :/i18n/cli/en_US.qm
     0.000 16168 debug dokit.cli.main: Library translations: :/i18n/lib/en_US.qm
     0.001 16168 debug dokit.cli.command: Set scan timeout to 180000
     0.001 16168 info dokit.cli.command: Looking for device "orange"...
     0.001 16168 debug pokit.ble.discovery: Scanning for Bluetooth Low Energy devices.
     0.205 16168 debug pokit.ble.discovery: Discovered Pokit device "orange" at 84:FD:27:86:C8:82.
     0.205 16168 debug dokit.cli.command: Found Pokit device "orange" ({00000000-0000-0000-0000-000000000000}) at (84:FD:27:86:C8:82).
     0.205 16168 debug pokit.ble.discovery: Pokit device scan cancelled.
     0.209 16168 debug pokit.ble.controller: Setting new controller: QLowEnergyController(0x27415a0bb40)
     0.209 16168 debug pokit.ble.controller: Set new controller "orange" ({00000000-0000-0000-0000-000000000000}) at (84:FD:27:86:C8:82).
     0.209 16168 debug dokit.cli.command: Connecting to Pokit Pro device "orange" ({00000000-0000-0000-0000-000000000000}) at (84:FD:27:86:C8:82).
     0.209 16168 debug pokit.ble.controller: State changed to: QLowEnergyController::ConnectingState
     5.443 16168 warning qt.bluetooth.windows: Could not await characteristic read
     5.443 16168 debug pokit.ble.controller: Controller error: QLowEnergyController::ConnectionError
     5.443 16168 debug pokit.ble.controller: State changed to: QLowEnergyController::UnconnectedState
     5.443 16168 warning dokit.cli.command: Bluetooth controller error: QLowEnergyController::ConnectionError
PS C:\Users\xxxxx\Downloads\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable\dokit-0.5.3+1375.win.x86-64.msvc.qt-6.8.0.portable> .\dokit -d orange logger-fetch --timeout 180s --debug
     0.000 7464 debug dokit.cli.main: Dokit 0.5.3+1375.win.x86-64.msvc.qt-6.8.0
     0.000 7464 debug dokit.cli.main: Qt 6.8.0 compile-time
     0.000 7464 debug dokit.cli.main: Qt 6.8.0 runtime
     0.000 7464 debug dokit.cli.main: App translations: :/i18n/cli/en_US.qm
     0.000 7464 debug dokit.cli.main: Library translations: :/i18n/lib/en_US.qm
     0.000 7464 debug dokit.cli.command: Set scan timeout to 180000
     0.001 7464 info dokit.cli.command: Looking for device "orange"...
     0.001 7464 debug pokit.ble.discovery: Scanning for Bluetooth Low Energy devices.
     0.287 7464 debug pokit.ble.discovery: Discovered Pokit device "orange" at 84:FD:27:86:C8:82.
     0.287 7464 debug dokit.cli.command: Found Pokit device "orange" ({00000000-0000-0000-0000-000000000000}) at (84:FD:27:86:C8:82).
     0.288 7464 debug pokit.ble.discovery: Pokit device scan cancelled.
     0.292 7464 debug pokit.ble.controller: Setting new controller: QLowEnergyController(0x1c08395a4d0)
     0.292 7464 debug pokit.ble.controller: Set new controller "orange" ({00000000-0000-0000-0000-000000000000}) at (84:FD:27:86:C8:82).
     0.292 7464 debug dokit.cli.command: Connecting to Pokit Pro device "orange" ({00000000-0000-0000-0000-000000000000}) at (84:FD:27:86:C8:82).
     0.292 7464 debug pokit.ble.controller: State changed to: QLowEnergyController::ConnectingState
     0.395 7464 debug pokit.ble.controller: State changed to: QLowEnergyController::ConnectedState
     0.395 7464 debug pokit.ble.controller: Connected to "orange" ({00000000-0000-0000-0000-000000000000}) at (84:FD:27:86:C8:82).
     0.395 7464 debug pokit.ble.service: Connected to "orange" ({00000000-0000-0000-0000-000000000000}) at 84:FD:27:86:C8:82.
     0.395 7464 debug pokit.ble.controller: State changed to: QLowEnergyController::DiscoveringState
     0.429 7464 debug pokit.ble.controller: Service discovered: {00001801-0000-1000-8000-00805f9b34fb} "Generic Attribute"
     0.439 7464 debug pokit.ble.controller: Service discovered: {00001800-0000-1000-8000-00805f9b34fb} "Generic Access"
     0.450 7464 debug pokit.ble.controller: Service discovered: {0000180a-0000-1000-8000-00805f9b34fb} "Device Information"
     0.460 7464 debug pokit.ble.controller: Service discovered: {57d3a771-267c-4394-8872-78223e92aec5} "Status (Pokit Pro)"
     0.471 7464 debug pokit.ble.controller: Service discovered: {e7481d2f-5781-442e-bb9a-fd4e3441dadc} "Multimeter"
     0.481 7464 debug pokit.ble.controller: Service discovered: {1569801e-1425-4a7a-b617-a4f4ed719de6} "DSO"
     0.491 7464 debug pokit.ble.controller: Service discovered: {a5ff3566-1fd8-4e10-8362-590a578a4121} "Data Logger"
     0.491 7464 debug pokit.ble.service: Service discovered {a5ff3566-1fd8-4e10-8362-590a578a4121}
     0.491 7464 debug pokit.ble.service: Service object created for Pokit Pro device: QLowEnergyService(0x1c082fa99e0)
     0.491 7464 debug pokit.ble.service: State changed to QLowEnergyService::RemoteServiceDiscovering
     0.516 7464 debug pokit.ble.controller: Service discovered: {6f53be2f-780b-49b8-a7c3-e8a052b3ae2c} "Calibration"
     0.527 7464 debug pokit.ble.controller: Service discovered: {3852ae6e-a1e6-4132-87f7-8929f6117338} ""
     0.538 7464 debug pokit.ble.controller: Service discovered: {ae97e4b0-9c1c-4507-bf7b-eff703c6a85c} ""
     0.549 7464 debug pokit.ble.controller: Service discovered: {1d14d6ee-fd63-4fa1-bfa4-8f47b42119f0} "OTA Firmware Update"
     0.549 7464 debug pokit.ble.controller: State changed to: QLowEnergyController::DiscoveredState
     0.549 7464 debug pokit.ble.controller: Service discovery finished.
     0.549 7464 debug pokit.ble.service: Discovery finished for "orange" ({00000000-0000-0000-0000-000000000000}) at 84:FD:27:86:C8:82.
     0.549 7464 debug pokit.ble.service: Already have service object: QLowEnergyService(0x1c082fa99e0)
     0.626 7464 debug pokit.ble.service: State changed to QLowEnergyService::RemoteServiceDiscovered
     0.626 7464 debug pokit.ble.service: Characteristic {5f97c62b-a83b-46c6-b9cd-cac59e130a78} "Settings" supports write.
     0.626 7464 debug pokit.ble.service: Characteristic {3c669dab-fc86-411c-9498-4f9415049cc0} "Reading" supports notify.
     0.626 7464 debug pokit.ble.service: Characteristic {9acada2e-3936-430b-a8f7-da407d97ca6e} "Metadata" supports read, notify.
     0.626 7464 debug pokit.ble.service: Service details discovered.
     0.626 7464 debug dokit.cli.command: Service details discovered.
     0.626 7464 info dokit.cli.command: Fetching logger samples...
     0.626 7464 debug pokit.ble.service: Enabling CCCD for characteristic {9acada2e-3936-430b-a8f7-da407d97ca6e} "Metadata".
     0.630 7464 debug pokit.ble.service: Enabling CCCD for characteristic {3c669dab-fc86-411c-9498-4f9415049cc0} "Reading".
     0.720 7464 debug pokit.ble.service: Descriptor "Client Characteristic Configuration" ({00002902-0000-1000-8000-00805f9b34fb}) written.
     0.824 7464 debug pokit.ble.service: Characteristic {9acada2e-3936-430b-a8f7-da407d97ca6e} "Metadata" changed to 23 bytes: 0x00,92,9f,1d,3a,00,00,10,27,...,00,30,38,00,00,3d,9e,95,67
     0.825 7464 debug pokit.ble.service: "10,27,00,00,30,00,00,00,30,38,00,00"
     0.825 7464 debug dokit.cli.command: status: 0
     0.827 7464 debug dokit.cli.command: scale: 0.000601285
     0.828 7464 debug dokit.cli.command: mode: "Idle" 0
     0.828 7464 debug dokit.cli.command: range: "" 0
     0.829 7464 debug dokit.cli.command: updateInterval: 10000
     0.829 7464 debug dokit.cli.command: numberOfSamples: 48
     0.835 7464 debug dokit.cli.command: timestamp: 1737858621 QDateTime(2025-01-26 02:30:21.000 UTC Qt::UTC)
     0.835 7464 info dokit.cli.command: Fetching 48 logger samples...
     0.835 7464 debug pokit.ble.service: Characteristic {5f97c62b-a83b-46c6-b9cd-cac59e130a78} "Settings" written with 13 bytes: 0x02,00,00,00,00,00,00,00,00,00,00,00,00
     0.982 7464 debug pokit.ble.service: Descriptor "Client Characteristic Configuration" ({00002902-0000-1000-8000-00805f9b34fb}) written.
     1.034 7464 debug pokit.ble.service: Characteristic {3c669dab-fc86-411c-9498-4f9415049cc0} "Reading" changed to 96 bytes: 0xff,7f,eb,7e,eb,7e,eb,7e,eb,...,7e,eb,7e,eb,7e,eb,7e,eb,7e
     1.035 7464 debug pokit.ble.service: Read 48 samples from 96-bytes.
     1.035 7464 debug dokit.cli.command: No known unit for mode 0 "Idle".

I removed some of the sample returns for brevity

2025-01-26T02:37:51.000Z 19.5364
2025-01-26T02:38:01.000Z 19.5364
2025-01-26T02:38:11.000Z 19.5364
     1.041 7464 info dokit.cli.command: Finished fetching 48 samples (with 0 remaining).
     1.042 7464 debug dokit.cli.command: Disconnecting Pokit device...
     1.042 7464 debug pokit.ble.service: State changed to QLowEnergyService::InvalidService
     1.042 7464 debug pokit.ble.service: Characteristic {5f97c62b-a83b-46c6-b9cd-cac59e130a78} "Settings" supports write.
     1.042 7464 debug pokit.ble.service: Characteristic {3c669dab-fc86-411c-9498-4f9415049cc0} "Reading" supports notify.
     1.042 7464 debug pokit.ble.service: Characteristic {9acada2e-3936-430b-a8f7-da407d97ca6e} "Metadata" supports read, notify.
     1.042 7464 debug pokit.ble.controller: State changed to: QLowEnergyController::ClosingState
     1.052 7464 debug pokit.ble.controller: State changed to: QLowEnergyController::UnconnectedState
     1.052 7464 debug pokit.ble.controller: Device disconnected.
     1.052 7464 debug dokit.cli.command: Pokit device disconnected. Exiting with code 0.

[pcolby]

THanks @ojg78, this looks like something internal to Qt's BLE implementation for Windows.

tl;dr Would you mind trying the one of the latest Qt 6.9 beta builds? eg dokit-0.5.4+1474.win.x86-64.msvc.qt-6.9.0.portable.zip (an official Dokit v0.5.4 release; just using Qt 6.9.0 beta).

Longer version: for curiosity, I had a look at where this error originates in the Qt Connectivity source code:

                // Reading characteristics can take surprisingly long at the
                // first time, so we need to have a large the timeout here.
                hr = QWinRTFunctions::await(op, result.GetAddressOf(),
                                            QWinRTFunctions::ProcessThreadEvents, 5000, earlyExit);
                // E_ILLEGAL_METHOD_CALL will be the result for a device, that is not reachable at
                // the moment. In this case we should jump back into the outer loop and keep trying.
                if (hr == E_ILLEGAL_METHOD_CALL)
                    break;
                EMIT_WORKER_ERROR_AND_QUIT_IF_FAILED_2(hr, "Could not await characteristic read");

It would be nice if Qt would log the value of hr here. Of course, that 5000 in the await call is the likely source of the 5 second timeout you're observing. And hr is probably just a code that indicates timeout, but it would still be nice to know which code precisely.

Anyway, what's more interesting, is that error message (Could not await characteristic read) doesn't exist in the current Qt HEAD. Indeed, it was removed (substantially refactored) by commit qt/qtconnectivity@a555237, which is included in Qt 6.9.0 beta 1 and 2. As of Qt 6.9.0, the entire Qt BLE backend for Windows is quite different, so I would be interested in seeing if you experience the same, or better or worse, with the Qt 6.9 build/s. Let us know if you get a chance to try it.

Thanks!

[ojg78]

I had a very brief time with this version and found it considerably more flaky with regards to getting a connection to the pokitpro. I will spend more time with it and get some logs over this week.