Bluetooth won't connect

[jmilliken]

Hello,

I am testing the peripheral_uart sample code on the U-blox NORA-B101 dev kit and also on our custom board. When I run it on the dev kit, I can connect. When I run the exact same code on our custom board, I can scan and see the device, but cannot connect. First screenshot below is the DEBUG log output from the nRF Connect app successfully connecting to the dev kit. The second screenshot is trying and failing to connect to our board. The error message is really not giving me enough detail to further debug the problem so I could use some guidance.

There are a few relevant differences between the dev kit and our board:

1. The dev kit uses the NORA-B101 which has an integrated antenna. Our board uses NORA-B106 with external SMD antenna. Signal strength from our board's broadcast is -100dB typical, which I think should be fine. Is there a way to assess the quality of the signal besides RSSI?
2. Our board uses the internal low frequency oscillator rather than external oscillator (which is what the dev kit has). I followed the instructions in the U-blox app note for configuring the clock this way, and I have a blinking LED so I know the code is running (plus I can see the board during the BLE scan). But am I missing something else in the clock configuration to get the BLE to work?

Thank you,

Jamie

[Turbo J]

A phone should read -60..-40dB when close to the module.

A reading of -100dB is either faulty or the antenna is disconnected (could also be blocked by metal). If the -100dB reading is roughly correct, expect a very bad connection quality and very low range.

[jmilliken]

Thanks, that is interesting. I played with the compensation network on the antenna and now signal strength is about -62dB, but I get the same behavior. Do you have any suggestions for further debugging?

Thank you,

Jamie

[jmilliken]

Hi. I have the RTT working, thanks. Using the peripheral_uart code without modifications, when I try to connect, I get the following:

This error code (from hci_err.h) is BT_HCI_ERR_CONN_TIMEOUT. It seems like the radio is starting since I can see the device broadcasting its ID. However, what does this mean: "bt_hci_core: No ID address. App must call settings_load()"

-Jamie

[jmilliken]

One more note - I added the following log message to the code to make sure that settings_load() was being called:

    if (IS_ENABLED(CONFIG_SETTINGS)) {

        int ret;

        ret = settings_load();

        LOG_INF("Called settings_load with return val: %d", ret);

    } else {

        LOG_INF("Did not call settings_load");

    }

 

RTT message output confirms that it is called:

[jmilliken]

I added CONFIG_BT_CTLR_TO_HOST_HCI_DEBUG=y to the prj.conf to get more verbose output on RTT. I got the following:

00> [00:01:07.556,060] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x200014d0 chan 0x2000178c
00> --- 43 messages dropped ---
00> [00:01:07.557,281] <dbg> bt_hci_core: process_events: ev->state 1
00> [00:01:07.557,312] <dbg> bt_conn: bt_conn_prepare_events:
00> --- 9 messages dropped ---
00> [00:01:07.558,502] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20006be0 opcode 0x2016 len 0
00> [00:01:07.558,532] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
00> [00:01:07.558,532] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20006be0
00> [00:01:07.558,624] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20006be0 opcode 0x2032 len 10
00> [00:01:07.558,715] <dbg> bt_hci_core: process_events: count 3
00> [00:01:07.558,746] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:07.558,746] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:07.558,776] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:07.558,776] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x20006be0) to driver
00> [00:01:07.558,837] <dbg> bt_hci_core: bt_send: buf 0x20006be0 len 10 type 0
00> [00:01:07.558,868] <dbg> bt_hci_driver: bt_rpmsg_send: buf 0x20006be0 type 0 len 10
00> [00:01:07.558,898] <dbg> bt_hci_driver: bt_rpmsg_send: Final HCI buffer:
00> 01 32 20 07 0f 00 00 02 02 00 00 |.2 ..... ...
00> [00:01:07.558,990] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:07.558,990] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:07.559,020] <dbg> bt_conn: bt_conn_prepare_events:
00> [00:01:07.559,082] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200014d0 to poll list
00> [00:01:07.559,112] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:07.559,875] <dbg> bt_hci_driver: bt_rpmsg_rx: RPMsg data:
00> 04 0f 04 00 01 32 20 |.....2
00> [00:01:07.559,967] <dbg> bt_hci_driver: bt_rpmsg_evt_recv: len 4
00> [00:01:07.559,967] <dbg> bt_hci_driver: bt_rpmsg_rx: Calling bt_recv(0x20006be0)
00> [00:01:07.559,997] <dbg> bt_hci_core: bt_recv: buf 0x20006be0 len 6
00> [00:01:07.560,058] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
00> [00:01:07.560,089] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x20006be0
00> [00:01:07.560,119] <dbg> bt_hci_driver: bt_rpmsg_rx: RX buf payload:
00> [00:01:07.560,211] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20006be0 opcode 0x2032 len 0
00> [00:01:07.560,241] <dbg> bt_conn: bt_conn_unref: handle 15 ref 3 -> 2
00> [00:01:12.556,060] <dbg> bt_conn: deferred_work: conn 0x200014d0
00> [00:01:12.556,091] <dbg> bt_conn: send_conn_le_param_update: conn 0x200014d0 features 0x00 params (24-40 0 42)
00> [00:01:12.556,152] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200014d0 cid 5 len 12
00> [00:01:12.556,182] <dbg> bt_conn: bt_conn_send_cb: conn handle 15 buf len 16 cb (nil) user_data (nil)
00> [00:01:12.556,213] <dbg> bt_hci_core: process_events: count 3
00> [00:01:12.556,274] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:12.556,304] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:12.556,304] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:12.556,335] <dbg> bt_conn: bt_conn_process_tx: conn 0x200014d0
00> [00:01:12.556,335] <dbg> bt_conn: send_buf: conn 0x200014d0 buf 0x20006fc0 len 16
00> [00:01:12.556,365] <dbg> bt_conn: send_frag: conn 0x200014d0 buf 0x20006fc0 len 16 flags 0x02
00> [00:01:12.556,427] <dbg> bt_hci_core: bt_send: buf 0x20006fc0 len 20 type 2
00> [00:01:12.556,457] <dbg> bt_hci_driver: bt_rpmsg_send: buf 0x20006fc0 type 2 len 20
00> [00:01:12.556,457] <dbg> bt_hci_driver: bt_rpmsg_send: Final HCI buffer:
00> 02 0f 00 10 00 0c 00 05 00 12 02 08 00 18 00 28 |........ .......(
00> 00 00 00 2a 00 |...*.
00> [00:01:12.556,579] <dbg> bt_conn: bt_conn_prepare_events:
00> [00:01:12.556,579] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200014d0 to poll list
00> [00:01:12.556,640] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:12.610,015] <dbg> bt_att: bt_att_disconnected: chan 0x2000467c cid 0x0004
00> --- 29 messages dropped ---
00> [00:01:12.610,015] <dbg> bt_att: att_chan_detach: chan 0x20004678
00> --- 8 messages dropped ---
00> [00:01:12.611,022] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:12.611,022] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising
00> [00:01:12.611,083] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
00> [00:01:12.611,114] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20006be0
00> [00:01:12.611,145] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20006be0 opcode 0x200a len 4
00> [00:01:12.611,236] <dbg> bt_hci_core: process_events: count 2
00> [00:01:12.611,267] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:12.611,267] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:12.611,328] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:12.611,358] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x20006be0) to driver
00> [00:01:12.611,389] <dbg> bt_hci_core: bt_send: buf 0x20006be0 len 4 type 0
00> [00:01:12.611,389] <dbg> bt_hci_driver: bt_rpmsg_send: buf 0x20006be0 type 0 len 4
00> [00:01:12.611,450] <dbg> bt_hci_driver: bt_rpmsg_send: Final HCI buffer:
00> 01 0a 20 01 01 |.. ..
00> [00:01:12.611,511] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:12.611,572] <dbg> bt_conn: bt_conn_prepare_events:
00> [00:01:12.611,602] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
00> [00:01:12.612,579] <dbg> bt_hci_driver: bt_rpmsg_rx: RPMsg data:
00> 04 0e 04 01 0a 20 00 |..... .
00> [00:01:12.612,609] <dbg> bt_hci_driver: bt_rpmsg_evt_recv: len 4
00> [00:01:12.612,609] <dbg> bt_hci_driver: bt_rpmsg_rx: Calling bt_recv(0x20006be0)
00> [00:01:12.612,670] <dbg> bt_hci_core: bt_recv: buf 0x20006be0 len 6
00> [00:01:12.612,701] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
00> [00:01:12.612,701] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x20006be0
00> [00:01:12.612,792] <dbg> bt_hci_driver: bt_rpmsg_rx: RX buf payload:
00> 00 |.
00> [00:01:12.612,854] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20006be0 opcode 0x200a len 1
00> [00:01:12.612,945] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1

[Vidar Berg]

Hi,

Thanks. The logs show that FW runs OK, but that the connection times out because the device stops receiving packets from the phone.

When you changed the LF clock source from the crystal oscillator to the internal RC, did you do it in the project settings, or in the board file? I am basically wondering if the same clock configuration has been applied to both the application and netcore image. I can also check it if you are able to upload your build folder here.

[jmilliken]

Hi Vidar. Thanks, I think this solved it. I added the following lines to the prj.conf of hci_rpmsg:

CONFIG_CLOCK_CONTROL_NRF_K32SRC_RC=y

CONFIG_CLOCK_CONTROL_NRF_K32SRC_500PPM=y

CONFIG_CLOCK_CONTROL_NRF_K32SRC_SYNTH=y

I then recompiled the whole project and flashed to my device. Now the phone connects and stays connected! Thanks for all the help.

One final question just so I can better understand in the future. You were able to determine that the device stops receiving packets by looking at the above log. Which lines, specifically, tipped you off to this? Is there an app note or guide on how to interpret these logs?

-Jamie

[Vidar Berg]

Hi Jamie,

I am glad to hear that it solved the problem. What happens when you enable the RC oscillator on the app core but forget to do the same in the network core FW is that the CLOCK_CONTROL_NRF_K32SRC_RC_CALIBRATION symbol will not default to =y and cause the system to run off the RC oscillator uncalibrated.

The uncalibrated RC oscillator has too much freq. drift to be used with BLE. The clock drift will cause the BLE controller (hci_rpmsg in this case) to wake up and listen for BLE packets at the wrong time. 

  

jmilliken said:

I added the following lines to the prj.conf of hci_rpmsg:

CONFIG_CLOCK_CONTROL_NRF_K32SRC_RC=y

CONFIG_CLOCK_CONTROL_NRF_K32SRC_500PPM=y

CONFIG_CLOCK_CONTROL_NRF_K32SRC_SYNTH=y

Note that only one of the sources (RC vs SYNTH) will end up being selected here since you are defining both. RC is generally the recommended choice for designs without the 32KHz crystal as the SYNTH source is not considered "low power". 

jmilliken said:

One final question just so I can better understand in the future. You were able to determine that the device stops receiving packets by looking at the above log. Which lines, specifically, tipped you off to this? Is there an app note or guide on how to interpret these

It was mostly just looking at the disconnect reason actually. Disconnect reason 8 corresponds to "connection timeout". The other logs just showed that there were no runtime errors and that the stack was operating as normal.