Issue connecting with slower advertising intervals

[krog1]

I am seeing that faster advertising intervals will connect OK, and slower ones will consistently not. Specifically, a min-max of 0x1100-0x1250 works, but 0x1200-0x1400 doesn't, as well as larger values of course. I don't have any problem connecting to the peripherals with nRF Connect on Android, regardless of the advertising interval, so I thought that it was something I was doing on the Central.

I can understand that it takes longer to pick up the peripheral on the scan, but looking at the traces on the central (I'm using a pca10090 dev board), it's finding the device OK in the scan, and the call to bt_conn_create_le() returns OK, but I get a connection failure callback with error 2, which appears to be BT_HCI_ERR_UNKNOWN_CONN_ID in hci_core.c. It looks like this is coming all the way from the softdevice on the nrf52840, but I didn't confirm with the debugger.

Since the device was found on the scan, I didn't think it was the scan parameters, but I tried several different options just in case. I posted this as a reply to a similar issue someone had posted a while ago (https://devzone.nordicsemi.com/f/nordic-q-a/49906/10s-advertising-interval-and-connection/219116) but that probably was the wrong forum.

I'm using v1.14.99-ncs1 of NCS for both the peripheral and central.

Thanks,

Chris.

[Kenneth]

We do not currently provide support for NCS for the nRF52-series, even if there are some Bluetooth related samples and libraries in NCS. 

That said, it may be useful if you can enable debug logs, especially for CONFIG_BT_DEBUG_HCI_CORE. Also please clarify which side is seeing the error code.

[krog1]

Hi Kenneth,

The error code is on the nrf9160, coming from the HCI code to the connect callback. the HCI_CORE debug trace is below. Hopefully it's enough; unfortunately some logs were dropped.

Thanks,

Chris.

---

[00:03:24.380,493] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x200d param_len 25
[00:03:24.380,523] <dbg> bt_hci_core.bt_hci_cmd_create: buf 0x200386d0
[00:03:24.380,615] <dbg> bt_hci_core.bt_hci_cmd_send_sync: buf 0x200386d0 opcode 0x200d len 28
[00:03:24.380,798] <dbg> bt_hci_core.process_events: count 2
[00:03:24.380,828] <dbg> bt_hci_core.process_events: ev->state 4
[00:03:24.380,859] <dbg> bt_hci_core.send_cmd: calling net_buf_get
[00:03:24.380,889] <dbg> bt_hci_core.send_cmd: calling sem_take_wait
[00:03:24.380,920] <dbg> bt_hci_core.send_cmd: Sending command 0x200d (buf 0x200386d0) to driver
[00:03:24.381,011] <dbg> bt_hci_core.bt_send: buf 0x200386d0 len 28 type 0
[00:03:24.381,134] <dbg> bt_hci_core.process_events: ev->state 0
[00:03:24.381,225] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 2 events
[00:03:24.381,958] <dbg> bt_hci_core.bt_buf_get_cmd_complete: sent_cmd 0x200386d0
[00:03:24.382,019] <dbg> bt_hci_core.hci_cmd_status: opcode 0x200d
[00:03:24.382,080] <dbg> bt_hci_core.hci_cmd_done: opcode 0x200d status 0x00 buf 0x200386d0
[00:03:24.382,232] <dbg> bt_hci_core.bt_hci_cmd_send_sync: opcode 0x200d status 0x00
[00:03:27.378,936] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x200e param_len 0
--- 1 messages dropped ---
[00:03:27.379,180] <dbg> bt_hci_core.send_cmd: Sending command 0x200e (buf 0x200386d0) to driver
--- 5 messages dropped ---
[00:03:27.379,211] <dbg> bt_hci_core.bt_send: buf 0x200386d0 len 3 type 0
[00:03:27.379,302] <dbg> bt_hci_core.process_events: ev->state 0
[00:03:27.379,364] <dbg> bt_hci_core.hci_tx_thread: Calling k_poll with 2 events
[00:03:27.379,699] <dbg> bt_hci_core.bt_buf_get_cmd_complete: sent_cmd 0x200386d0
[00:03:27.379,730] <dbg> bt_hci_core.hci_cmd_complete: opcode 0x200e
[00:03:27.379,760] <dbg> bt_hci_core.hci_cmd_done: opcode 0x200e status 0x00 buf 0x200386d0
[00:03:27.380,218] <dbg> bt_hci_core.bt_recv: buf 0x20038798 len 21
[00:03:27.380,218] <dbg> bt_hci_core.hci_event: event 0x3e
[00:03:27.380,249] <dbg> bt_hci_core.hci_le_meta_event: subevent 0x01
[00:03:27.380,371] <dbg> bt_hci_core.le_legacy_conn_complete: status 2 role 0 00:00:00:00:00:00 (public)
[00:03:27.380,493] <dbg> bt_hci_core.enh_conn_complete: status 2 handle 0 role 0 00:00:00:00:00:00 (public)
[00:03:27.380,584] <wrn> ble: Failed to connect to cf:ae:17:85:49:78 (random) (error 2)

[Kenneth]

What you are seeing is that the connect operation was canceled. Successfully.

So it seems that the connect procedure timed out because the advertising interval was too high. The cancel operation was most likely coming from this: CONFIG_BT_CREATE_CONN_TIMEOUT, which is default 3. You should increase it in this use case.

Best regards,
Kenneth

[krog1]

Thanks Kenneth! That took care of it.

Cheers,

Chris.