Inconsistent behavior when connecting from Custom BLE device to nrf52dk running different SDKs

[Alexandr Kolodinsky]

We have a Сustom BLE device and observe inconsistent behavior when connecting from this device to to nrf52dk running different SDK versions.

- Custom Device connects OK with DK running SDK 13.1 / Soft Device ver: s132_nrf52_4.0.2_softdevice.hex
- Custom Device connects and immediately disconnects from DK running SDK 14.0 / Soft Device ver: s132_nrf52_5.0.0_softdevice.hex
- Custom Device doesn't have debug BlueZ output capability
- Alternative Reference Device (Raspi3, Raspbian Jessie) connects OK to all SDK-s from the list above

DK and application used:
- Hardware: Nordic nrf52dk pca10040
- Application: examples/ble_peripheral/ble_app_alert_notification

Custom Device info:
- Debian-based
- Linux kernel version: 3.14.79-xmm7272
- Bluez version 5.49

Based on DevZone posts, the suspicion was SDK 13 might have different clock settings vs. 14+. To validate this, we captured some registers' values in both 13 and 14 SDKs:
- NRF_CLOCK clock registers values right after enabling BLE stack
- Radio registers (NRF_RADIO->MODE and NRF_RADIO->MODECNF0) after successful connection to DK
Register values appeared to be exactly same in both cases.

Below are some logs examples when connecting Custom Device to DK.

1) SDK 13.1.0. Successful connection from Custom Device to DK

bluetoothctl output:
-----------------------
[bluetooth]# connect C7:81:0E:7B:BE:0B
Attempting to connect to C7:81:0E:7B:BE:0B
[CHG] Device C7:81:0E:7B:BE:0B Connected: yes
Connection successful
[NEW] Primary Service
/org/bluez/hci0/dev_C7_81_0E_7B_BE_0B/service000a
00001801-0000-1000-8000-00805f9b34fb
Generic Attribute Profile
[NEW] Characteristic
/org/bluez/hci0/dev_C7_81_0E_7B_BE_0B/service000a/char000b
00002a05-0000-1000-8000-00805f9b34fb
Service Changed
[NEW] Descriptor
/org/bluez/hci0/dev_C7_81_0E_7B_BE_0B/service000a/char000b/desc000d
00002902-0000-1000-8000-00805f9b34fb
Client Characteristic Configuration
[CHG] Device C7:81:0E:7B:BE:0B UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device C7:81:0E:7B:BE:0B UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device C7:81:0E:7B:BE:0B ServicesResolved: yes
[CHG] Device C7:81:0E:7B:BE:0B Paired: yes
[Nordic_Alert_Notif.]# disconnect
Attempting to disconnect from C7:81:0E:7B:BE:0B
[CHG] Device C7:81:0E:7B:BE:0B ServicesResolved: no
Successful disconnected
[CHG] Device C7:81:0E:7B:BE:0B Connected: no

nrf52dk output:
------------------
APP:INFO:Alert Notification client example started.
APP:INFO:Fast advertising
NRF_CLOCK->TASKS_HFCLKSTART 0x0
NRF_CLOCK->TASKS_HFCLKSTART 0x0
NRF_CLOCK->TASKS_HFCLKSTOP 0x0
NRF_CLOCK->TASKS_LFCLKSTART 0x0
NRF_CLOCK->TASKS_LFCLKSTOP 0x0
NRF_CLOCK->TASKS_CAL 0x0
NRF_CLOCK->TASKS_CTSTART 0x0
NRF_CLOCK->TASKS_CTSTOP 0x0
NRF_CLOCK->EVENTS_HFCLKSTARTED 0x0
NRF_CLOCK->EVENTS_LFCLKSTARTED 0x0
NRF_CLOCK->EVENTS_DONE 0x0
NRF_CLOCK->EVENTS_CTTO 0x0
NRF_CLOCK->INTENSET 0x0
NRF_CLOCK->INTENCLR 0x0
NRF_CLOCK->HFCLKRUN 0x0
NRF_CLOCK->HFCLKSTAT 0x10000
NRF_CLOCK->LFCLKRUN 0x1
NRF_CLOCK->LFCLKSTAT 0x10001
NRF_CLOCK->LFCLKSRCCOPY 0x1
NRF_CLOCK->LFCLKSRC 0x1
NRF_CLOCK->CTIV 0x0
NRF_CLOCK->TRACECONFIG 0x0
APP:INFO:Alert Notification client example started.
APP:INFO:Fast advertising
APP:INFO:Slow advertising
APP:INFO:Connected.
APP:INFO:NRF_RADIO->MODE 0x0
APP:INFO:NRF_RADIO->MODECNF0 0x200
APP:INFO:Start encryption.
APP:INFO:Connection secured: role: 1, conn_handle: 0x0, procedure: 1.
APP:INFO:Disconnected.
APP:INFO:Fast advertising

2) SDK 14.0.0. Connection and immediate disconnection from Custom Device to DK

bluetoothctl output:
-----------------------
[bluetooth]# connect C7:81:0E:7B:BE:0B
Attempting to connect to C7:81:0E:7B:BE:0B
[CHG] Device C7:81:0E:7B:BE:0B Connected: yes
Connection successful
[CHG] Device C7:81:0E:7B:BE:0B Connected: no

nrf52dk output:
-------------------
<info> app: NRF_CLOCK->TASKS_HFCLKSTART 0x0
<info> app: NRF_CLOCK->TASKS_HFCLKSTART 0x0
<info> app: NRF_CLOCK->TASKS_HFCLKSTOP 0x0
<info> app: NRF_CLOCK->TASKS_LFCLKSTART 0x0
<info> app: NRF_CLOCK->TASKS_LFCLKSTOP 0x0
<info> app: NRF_CLOCK->TASKS_CAL 0x0
<info> app: NRF_CLOCK->TASKS_CTSTART 0x0
<info> app: NRF_CLOCK->TASKS_CTSTOP 0x0
<info> app: NRF_CLOCK->EVENTS_HFCLKSTARTED 0x0
<info> app: NRF_CLOCK->EVENTS_LFCLKSTARTED 0x0
<info> app: NRF_CLOCK->EVENTS_DONE 0x0
<info> app: NRF_CLOCK->EVENTS_CTTO 0x0
<info> app: NRF_CLOCK->INTENSET 0x0
<info> app: NRF_CLOCK->INTENCLR 0x0
<info> app: NRF_CLOCK->HFCLKRUN 0x0
<info> app: NRF_CLOCK->HFCLKSTAT 0x10000
<info> app: NRF_CLOCK->LFCLKRUN 0x1
<info> app: NRF_CLOCK->LFCLKSTAT 0x10001
<info> app: NRF_CLOCK->LFCLKSRCCOPY 0x1
<info> app: NRF_CLOCK->LFCLKSRC 0x1
<info> app: NRF_CLOCK->CTIV 0x0
<info> app: NRF_CLOCK->TRACECONFIG 0x0
<info> app: Alert Notification client example started.
<info> app: Fast advertising
<info> app: Connected.
<info> app: NRF_RADIO->MODE 0x0
<info> app: NRF_RADIO->MODECNF0 0x200
<info> app: Disconnected.
<info> app: Fast advertising

Our goal is to either somehow configure SDK 14+ to support connectivity to it from this device or at least be able to understand what is preventing from successful connection.
Any help will be much appreciated!

[Alexandr Kolodinsky]

Results are 100% consistent:

• connectivity never fails when connecting to DK running SDK 13.1
• connectivity always fails when connecting to DK running SDK 14+

As per above, RC clock source was also validated, just with a different setting:

NRF_SDH_CLOCK_LF_RC_TEMP_CTIV 4 (not 2 as you propose, unlikely this is significant).

If it was soldering or RF problem - why would it then work OK with SDK 13.1? What is so significantly different between these?

Thanks!

[Sigurd]

Alexandr Kolodinsky said:

What is so significantly different between these?

One significant difference is that s132_nrf52_5.0.0_softdevice is a Bluetooth 5 qualified SoftDevice and uses Channel Selection algorithm #2. It could be that Bluez somwhow does not handle this correctly.

Do you see the same issue with SDK 15.2 ? 

A sniffer trace could be helpful(see this page).

[Alexandr Kolodinsky]

Yes, the issue is the same with SDK 15.2. I can't yet post the sniffer log for security reasons, but you last answer lead to a different DevZone issue where ChSel #1 / #2 is discussed.

Sniffer logs analysis has shown that:

• Our custom BLE Central device always offers ChSel #2
• DK running SDK 13 as Peripheral offers ChSel #1
• DK running SDK 14+ as Peripheral offers ChSel #2

Apparently when both devices offer #2 - they use it and this isn't handled correctly.

Is there a way to explicitly control ChSel #1 / #2 in Nordic SDK? At least for debugging purposes we'd like to try SDK 14+ with ChSel #1 offer. Is it possible?

Thank you for your help!

[Sigurd]

Alexandr Kolodinsky said:

Is there a way to explicitly control ChSel #1 / #2 in Nordic SDK?

No, that is not possible. The SoftDevice is following the BLE spec, so I would recommend reporting this issue to the Bluez developers. (I see that Bluez version 5.50 is released, so it might be a chance that it’s fixed in that version.)