Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Device connection time is too long #220

Open
albertmoravec opened this issue Jan 29, 2025 · 6 comments
Open

Device connection time is too long #220

albertmoravec opened this issue Jan 29, 2025 · 6 comments
Labels
question Further information is requested

Comments

@albertmoravec
Copy link

We have identified that for our devices the Android nRF Connect Device Manager app and the library take very long time to connect on certain Android devices, while the nRF Connect app is significantly and consistently faster when connecting to the very same device.

From our testing we have seen connection times to usually be above 20 seconds and occasionally timeouting, while the nRF Connect app is always < 10s.

We have tried to rule out additional factors, but ultimately cannot figure out what's the reason for this behavior, as nRF Connect app is closed-source. Could you maybe point us to some differences in the connection process that might cause this?

Below I attached logs of our trial with Device Manager app where we sent an echo request to the device. The first connection attempt timeouted, the second one still took 7 second to connect. nRF Connect took 300 milliseconds to connect to the device.

Android device used

Honor Pad X8 (AGM3-W09HN)
Android 12

Logs

Device Manager

****************** [Device Manager] FIRST CONNECT ******************
2025-01-29 15:47:23.810 22636-22636 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  connect() - device: C5:61:0E:**:**:**, auto: false
2025-01-29 15:47:23.810 22636-22636 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  registerApp()
2025-01-29 15:47:23.811 22636-22636 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  registerApp() - UUID=4632415d-8ad0-493a-b514-7e6168b8b692
2025-01-29 15:47:23.815 22636-22647 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onClientRegistered() - status=0 clientIf=13
2025-01-29 15:47:23.830 22636-22636 HwViewRootImpl          no....droid.nrfconnectdevicemanager  I  removeInvalidNode all the node in jank list is out of time
2025-01-29 15:47:40.350 22636-22640 ctdevicemanage          no....droid.nrfconnectdevicemanager  I  Background concurrent copying GC freed 7594KB AllocSpace bytes, 16(856KB) LOS objects, 49% free, 7471KB/14MB, paused 145us,52us total 133.556ms
2025-01-29 15:47:53.827 22636-22705 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onClientConnectionState() - status=133 clientIf=13 device=C5:61:0E:**:**:**
2025-01-29 15:47:53.829 22636-22692 j                       no....droid.nrfconnectdevicemanager  W  Error: (0x85): GATT ERROR
2025-01-29 15:47:53.855 22636-22692 j                       no....droid.nrfconnectdevicemanager  W  Connection attempt timed out
2025-01-29 15:47:53.865 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  close()
2025-01-29 15:47:53.866 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  unregisterApp() - mClientIf=13
2025-01-29 15:47:53.898 22636-22636 HwViewRootImpl          no....droid.nrfconnectdevicemanager  I  removeInvalidNode all the node in jank list is out of time

****************** [Device Manager] RETRY ******************
2025-01-29 15:48:26.899 22636-22636 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  connect() - device: C5:61:0E:**:**:**, auto: false
2025-01-29 15:48:26.899 22636-22636 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  registerApp()
2025-01-29 15:48:26.899 22636-22636 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  registerApp() - UUID=6aba9fb7-ef08-4d1c-ad21-966a9d564e1d
2025-01-29 15:48:26.903 22636-22705 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onClientRegistered() - status=0 clientIf=13
2025-01-29 15:48:33.489 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onClientConnectionState() - status=0 clientIf=13 device=C5:61:0E:**:**:**
2025-01-29 15:48:33.490 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Connected to C5:61:0E:48:14:A0
2025-01-29 15:48:33.816 22636-22709 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  discoverServices() - device: C5:61:0E:**:**:**
2025-01-29 15:48:33.859 22636-22647 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onConnectionUpdated() - Device=C5:61:0E:**:**:** interval=6 latency=0 timeout=500 status=0
2025-01-29 15:48:33.860 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)
2025-01-29 15:48:35.853 22636-22644 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onSearchComplete() = Device=C5:61:0E:**:**:** Status=0
2025-01-29 15:48:35.854 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Services discovered
2025-01-29 15:48:35.907 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  configureMTU() - device: C5:61:0E:**:**:** mtu: 498
2025-01-29 15:48:35.960 22636-22644 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onConnectionUpdated() - Device=C5:61:0E:**:**:** interval=39 latency=0 timeout=500 status=0
2025-01-29 15:48:35.960 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Connection parameters updated (interval: 48.75ms, latency: 0, timeout: 5000ms)
2025-01-29 15:48:36.053 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onConfigureMTU() - Device=C5:61:0E:**:**:** mtu=498 status=0
2025-01-29 15:48:36.053 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  MTU changed to: 498
2025-01-29 15:48:36.066 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  setCharacteristicNotification() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48 enable: true
2025-01-29 15:48:36.070 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  writeDescriptor() - uuid: 00002902-0000-1000-8000-00805f9b34fb
2025-01-29 15:48:36.149 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onDescriptorWrite() - Device=C5:61:0E:**:**:** handle=96
2025-01-29 15:48:36.150 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Data written to descr. 00002902-0000-1000-8000-00805f9b34fb
2025-01-29 15:48:36.162 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Notifications enabled
2025-01-29 15:48:36.175 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  writeCharacteristic() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.183 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onCharacteristicWrite() - Device=C5:61:0E:**:**:** handle=95 Status=0
2025-01-29 15:48:36.183 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.251 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onNotify() - Device=C5:61:0E:**:**:** handle=95
2025-01-29 15:48:36.253 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 01-00-00-19-00-00-FF-06-BF-68-62-75-66-5F-73-69-7A-65-19-04-00-69-62-75-66-5F-63-6F-75-6E-74-0C-FF
2025-01-29 15:48:36.273 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Wait for value changed complete
2025-01-29 15:48:36.290 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onPhyRead() - status=0 address=C5:61:0E:**:**:** txPhy=1 rxPhy=1
2025-01-29 15:48:36.309 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Received Header (Version: 0, Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 255, Command: 6) CBOR {"buf_size":1024,"buf_count":12}
2025-01-29 15:48:36.370 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  SMP reassembly supported with buffer size: 1024 bytes and count: 12
2025-01-29 15:48:36.380 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  PHY read (TX: LE 1M, RX: LE 1M)
2025-01-29 15:48:36.395 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Sending (12 bytes) Header (Version: 1, Op: 2, Flags: 0, Len: 4, Group: 0, Seq: 0, Command: 0) CBOR {"d":""}
2025-01-29 15:48:36.403 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  writeCharacteristic() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.407 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onCharacteristicWrite() - Device=C5:61:0E:**:**:** handle=95 Status=0
2025-01-29 15:48:36.409 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Sending (9 bytes) Header (Version: 1, Op: 0, Flags: 0, Len: 1, Group: 0, Seq: 1, Command: 6) CBOR {}
2025-01-29 15:48:36.418 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.426 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  writeCharacteristic() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.430 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onCharacteristicWrite() - Device=C5:61:0E:**:**:** handle=95 Status=0
2025-01-29 15:48:36.430 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.494 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onNotify() - Device=C5:61:0E:**:**:** handle=95
2025-01-29 15:48:36.495 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 0B-00-00-05-00-00-00-00-BF-61-72-60-FF
2025-01-29 15:48:36.498 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onNotify() - Device=C5:61:0E:**:**:** handle=95
2025-01-29 15:48:36.507 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 09-00-00-19-00-00-01-06-BF-68-62-75-66-5F-73-69-7A-65-19-04-00-69-62-75-66-5F-63-6F-75-6E-74-0C-FF
2025-01-29 15:48:36.520 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Received Header (Version: 1, Op: 3, Flags: 0, Len: 5, Group: 0, Seq: 0, Command: 0) CBOR {"r":""}
2025-01-29 15:48:36.532 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Received Header (Version: 1, Op: 1, Flags: 0, Len: 25, Group: 0, Seq: 1, Command: 6) CBOR {"buf_size":1024,"buf_count":12}
2025-01-29 15:48:36.591 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Sending (19 bytes) Header (Version: 1, Op: 0, Flags: 0, Len: 11, Group: 0, Seq: 2, Command: 7) CBOR {"format":"sv"}
2025-01-29 15:48:36.605 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  writeCharacteristic() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.610 22636-22705 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onCharacteristicWrite() - Device=C5:61:0E:**:**:** handle=95 Status=0
2025-01-29 15:48:36.610 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.788 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onNotify() - Device=C5:61:0E:**:**:** handle=95
2025-01-29 15:48:36.789 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 09-00-00-17-00-00-02-07-BF-66-6F-75-74-70-75-74-6D-5A-65-70-68-79-72-20-33-2E-36-2E-39-39-FF
2025-01-29 15:48:36.803 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Received Header (Version: 1, Op: 1, Flags: 0, Len: 23, Group: 0, Seq: 2, Command: 7) CBOR {"output":"Zephyr 3.6.99"}
2025-01-29 15:48:36.838 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Sending (9 bytes) Header (Version: 1, Op: 0, Flags: 0, Len: 1, Group: 0, Seq: 3, Command: 8) CBOR {}
2025-01-29 15:48:36.849 22636-22692 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  writeCharacteristic() - uuid: da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.854 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onCharacteristicWrite() - Device=C5:61:0E:**:**:** handle=95 Status=0
2025-01-29 15:48:36.854 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Data written to da2e7828-fbce-4e01-ae9e-261174997c48
2025-01-29 15:48:36.933 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onNotify() - Device=C5:61:0E:**:**:** handle=95
2025-01-29 15:48:36.933 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Notification received from da2e7828-fbce-4e01-ae9e-261174997c48, value: (0x) 09-00-00-06-00-00-03-08-BF-62-72-63-08-FF
2025-01-29 15:48:36.945 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Received Header (Version: 1, Op: 1, Flags: 0, Len: 6, Group: 0, Seq: 3, Command: 8) CBOR {"rc":8}
2025-01-29 15:48:38.790 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onConnectionUpdated() - Device=C5:61:0E:**:**:** interval=9 latency=0 timeout=42 status=0
2025-01-29 15:48:38.791 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Connection parameters updated (interval: 11.25ms, latency: 0, timeout: 420ms)
2025-01-29 15:48:42.037 22636-22655 BluetoothGatt           no....droid.nrfconnectdevicemanager  D  onConnectionUpdated() - Device=C5:61:0E:**:**:** interval=32 latency=0 timeout=42 status=0
2025-01-29 15:48:42.038 22636-22692 j                       no....droid.nrfconnectdevicemanager  I  Connection parameters updated (interval: 40.0ms, latency: 0, timeout: 420ms)

nRF Connect

****************** [nRF Connect] FIRST CONNECT ******************
2025-01-29 15:51:30.336 23039-23039 BluetoothGatt           no.nordicsemi.android.mcp            D  connect() - device: C5:61:0E:**:**:**, auto: false
2025-01-29 15:51:30.336 23039-23039 BluetoothGatt           no.nordicsemi.android.mcp            D  registerApp()
2025-01-29 15:51:30.336 23039-23039 BluetoothGatt           no.nordicsemi.android.mcp            D  registerApp() - UUID=c69510b4-fa23-498d-b3ff-26550050b532
2025-01-29 15:51:30.340 23039-23098 BluetoothGatt           no.nordicsemi.android.mcp            D  onClientRegistered() - status=0 clientIf=12
2025-01-29 15:51:30.674 23039-23098 BluetoothGatt           no.nordicsemi.android.mcp            D  onClientConnectionState() - status=0 clientIf=12 device=C5:61:0E:**:**:**
2025-01-29 15:51:30.683 23039-23098 Compatibil...geReporter no.nordicsemi.android.mcp            D  Compat change id reported: 150939131; UID 10158; state: ENABLED
2025-01-29 15:51:30.690 23039-23039 BluetoothGatt           no.nordicsemi.android.mcp            D  discoverServices() - device: C5:61:0E:**:**:**
2025-01-29 15:51:31.087 23039-23098 BluetoothGatt           no.nordicsemi.android.mcp            D  onConnectionUpdated() - Device=C5:61:0E:**:**:** interval=6 latency=0 timeout=500 status=0
2025-01-29 15:51:33.124 23039-23049 BluetoothGatt           no.nordicsemi.android.mcp            D  onSearchComplete() = Device=C5:61:0E:**:**:** Status=0
2025-01-29 15:51:33.231 23039-23049 BluetoothGatt           no.nordicsemi.android.mcp            D  onConnectionUpdated() - Device=C5:61:0E:**:**:** interval=39 latency=0 timeout=500 status=0
2025-01-29 15:51:33.321 23039-23045 emi.android.mc          no.nordicsemi.android.mcp            I  Background concurrent copying GC freed 4246KB AllocSpace bytes, 0(0B) LOS objects, 49% free, 7260KB/14MB, paused 130us,49us total 147.757ms
2025-01-29 15:51:33.368 23039-23047 System                  no.nordicsemi.android.mcp            W  A resource failed to call close. 
2025-01-29 15:51:33.368 23039-23047 System                  no.nordicsemi.android.mcp            W  A resource failed to call close. 
2025-01-29 15:51:36.373 23039-23055 BluetoothGatt           no.nordicsemi.android.mcp            D  onConnectionUpdated() - Device=C5:61:0E:**:**:** interval=32 latency=0 timeout=42 status=0

Device used

nRF52833 (Zephyr softdevices BT controller) with split controller and host, with host running on nRF9151.

cc @optical-o

@philips77
Copy link
Member

Hello,
What is your advertising interval?
Both apps are using the same native API, so the behavior should be exactly the same. nRF C.D.M. is using the BLE library while nRF Connect has been implemented before that library existed, so it has its own implementation, but the behavior should be the same. I have never seen any difference when using these apps and sample apps from nRF Connect SDK or nRF5 SDK, but they use quite fast advertising and random static addresses.

This 30 seconds timeout may indicate, that the device isn't advertising at all or is out of range.
Did you try the same on another phone or tablet?

@philips77 philips77 added the question Further information is requested label Feb 4, 2025
@optical-o
Copy link

The advertising interval is set to 800ms. I have tested lower advertising intervals and the problem is not connected to the advertising interval.

We are pretty sure that the advertisements are sent to our custom implementation and even receive them, but the connection is taking a long time.

We have retested this behaviour with the App Store Device Manager vs nRF connect. Should we gather more logs? Do you have some guidance on how we can gather additional info around this?

@philips77
Copy link
Member

You may try sniffing it, for example using nRF Sniffer. When you have logs, please open a case on DevZone. I think our Support Team will be more qualified to help you with this issue.

@optical-o
Copy link

The main point was that the nRF Connect do not display this issue with a long connection and the nRF Device Manager does. So we are most likely drawn into the direction of the software problem inside the nRF Device Manager library. Any guidance on how to proceed to rule out the software would be appreciative.

I will also examine using nRF sniffer the connection itself, but we are using the SoftDevice controller that is closed source and we are unable to do anything there. The devzone issue is the last resort for us since we cannot share the whole application an we are unable to reproduce some minimal samples easily, which will have to try and dedicate a large amount of resources there.

@philips77
Copy link
Member

Let me clarify what I understand:

nRF Connect Device Manager

  1. You can scan and see the device advertising.
  2. You click it and tap "Send" on the Echo pane to connect.
  3. The connection takes very long time and sometimes times out.

Did you modify the nRF Connect Device Manager app in any way, or are you using version from Google Play Store?

nRF Connect

  1. You can can and see the device advertising as connectable (has CONNECT button).
  2. After clicking CONNECT the connection takes at most 9 seconds.
  3. Service discovery takes aroud 2 seconds.

When you scan the device, do you see the interval calculated as ~ 800 ms? Are all packets the same, if you open packet history (clikc MORE button on expended row)?

So we are most likely drawn into the direction of the software problem inside the nRF Device Manager library.

Both apps use the same public Android API for connection. Did you try connecting with other devices / DKs / samples from nRF Connect SDK? Do you see similar behavior, for example for SMP Server Sample from Zephyr?

@optical-o
Copy link

optical-o commented Feb 5, 2025

I have recorded two videos. The second is probably the more telling of what is happening when I open both of the applications at the same time nrf connect and device manager. Where you can see that the scanning nRF Connect is showing RIDER name which indicates that the connectable advertisement containing the device name is received by the Android. Here is the question why the android does not initiate the connection? By any means the nRF Connect app is without issues with the connection, however, overall it handles the connections faster it seems. This Android device(Honor Tablet) is the worst case we have seen but the issue is present even on phones that do scan much better (This device sees only a fraction of the advertising packets). Note that sometimes it connects immediately but we are troubleshooting the cases when it takes over 30s or event time outs.

nRF Connect Only: Video
Device Manager: Video

Screen of Scanning of another Android Device (Better Scanning) OnePlus:

Screen of Scanning of another Android Device (Better Scanning) Samsung S24:

I will try to obtain a capture from the sniffer where I can simply filter the Connactable advertisements for further debugging.
Should I somehow export the packets captured by the nrf connects on different phones?

Our application broadcasts multiple advertisements. The problem is that when using a singular advertisement and sample, which does nothing will most likely work. This is the case with most of the nRF Connect SDK samples. When we introduce a larger workload on the stack in this case 3 advertisements(all 800ms as max of the advertising interval) and background scanning of the Bluetooth Controller. Things do not behave as we would expect.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
question Further information is requested
Projects
None yet
Development

No branches or pull requests

3 participants