BLE connection to paired device failed after some time.

[D233374]

Hello.

I'm trying to use a nrf52840 as a central device and connect to a gopro13. The connection works a certain number of times. But after a while (several days or maybe several connections), the connection fails. Other devices (phone, remote control) successfully connect to the GoPro. If I start the pairing process on the GoPro, the connection will be successful and will work for some time.

More details:

My device is based on  Ebyte E73-2G4M08S1C module. 

My device shematic:

Project code - https://github.com/Sergey1560/nrf52_gopro_zephyr 

NRF Connect SDK v3.1.1

When I first connect to the GoPro, I select pairing mode on the camera. The connection is successful.

Do I need to save the connection settings separately afterward, or are they saved automatically?

At startup, I load the saved settings and display messages to monitor this:

err = bt_conn_auth_cb_register(&conn_auth_callbacks);
	if (err) {
		LOG_ERR("Failed to register authorization callbacks.");
		return 0;
	}

	err = bt_conn_auth_info_cb_register(&conn_auth_info_callbacks);
	if (err) {
		LOG_ERR("Failed to register authorization info callbacks.\n");
		return 0;
	}

	err = bt_enable(NULL);
	if (err) {
		LOG_ERR("Bluetooth init failed (err %d)", err);
		return 0;
	}
	LOG_INF("Bluetooth initialized");

	err=settings_load();
	if(err != 0){
		LOG_ERR("Settings load err: %d",err);
	}else{
		LOG_DBG("Settings load done");
	}

	scan_init();
	err = scan_start();
	if (err) {
		return 0;
	}

In the scan function, I check that there are saved connection settings to ignore other cameras that may be nearby:

static void try_add_address_filter(const struct bt_bond_info *info, void *user_data){
	int err;
	char addr[BT_ADDR_LE_STR_LEN];
	uint8_t *filter_mode = user_data;

	bt_addr_le_to_str(&info->addr, addr, sizeof(addr));

	LOG_DBG("Saved bond found: %s",addr);

	struct bt_conn *conn = bt_conn_lookup_addr_le(BT_ID_DEFAULT, &info->addr);

	if (conn) {
		bt_conn_unref(conn);
		return;
	}
	
	err = bt_scan_filter_add(BT_SCAN_FILTER_TYPE_ADDR, &info->addr);
	if (err) {
		LOG_ERR("Address filter cannot be added (err %d): %s", err, addr);
		return;
	}

	LOG_INF("Address filter added: %s", addr);
	*filter_mode |= BT_SCAN_ADDR_FILTER;
}


static int scan_start(void){
	int err;
	uint8_t filter_mode = 0;

	err = bt_scan_stop();
	if (err) {
		LOG_ERR("Failed to stop scanning (err %d)", err);
		return err;
	}

	bt_scan_filter_remove_all();
	bt_foreach_bond(BT_ID_DEFAULT, try_add_address_filter, &filter_mode);

	if((filter_mode & BT_SCAN_ADDR_FILTER) == 0){
		LOG_DBG("Saved bonds not found, filter by UUID");
		filter_mode = BT_SCAN_UUID_FILTER;	

		err = bt_scan_filter_add(BT_SCAN_FILTER_TYPE_UUID, BT_UUID_GOPRO_SERVICE);
		if (err) {
			LOG_ERR("UUID filter cannot be added (err %d", err);
			return err;
		}
	}

	err = bt_scan_filter_enable(filter_mode, false);
	if (err) {
		LOG_ERR("Filters cannot be turned on (err %d)", err);
		return err;
	}

	err = bt_scan_start(BT_SCAN_TYPE_SCAN_ACTIVE);
	if (err) {
		LOG_ERR("Scanning failed to start (err %d)", err);
		return err;
	}

	led_idle_timer_start(1);
	LOG_INF("Scan started");
	return 0;
}

Debug output when connection fails:

<dbg> can_mcp2515: mcp2515_init: Presc: 2, BS1: 7, BS2: 2
[00:00:00.001,007] <dbg> can_mcp2515: mcp2515_init: Sample-point err : 0
*** Booting nRF Connect SDK v3.1.1-e2a97fe2578a ***
*** Using Zephyr OS v4.1.99-ff8f0c579eeb ***
[00:00:14.203,155] <dbg> gopro_main: clocks_start: HF clock started
[00:00:14.203,216] <inf> gopro_leds: Set up LED at GPIO_0 pin 28
[00:00:14.203,247] <inf> gopro_leds: Set up LED at GPIO_1 pin 11
[00:00:14.203,369] <dbg> canbus_gopro: canbus_init: CAN device ready
[00:00:14.203,369] <dbg> canbus_gopro: canbus_init: MODE NORMAL Enabled.
[00:00:14.204,406] <inf> canbus_gopro: CAN Start
[00:00:14.204,467] <inf> canbus_gopro: CAN BUS init done
[00:00:14.212,280] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:14.212,280] <inf> fs_nvs: alloc wra: 0, fb8
[00:00:14.212,310] <inf> fs_nvs: data wra: 0, 8c
[00:00:14.212,493] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
                                            fc de 41 eb a2 d1 42 24  00 b5 f8 57 9f ac 9d 9e |..A...B$ ...W....
                                            aa c9 b4 34                                      |...4             
[00:00:14.216,888] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:14.216,949] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:14.216,979] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 252.16862 Build 1121034987
[00:00:14.217,407] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:14.217,407] <inf> gopro_discovery: Bluetooth initialized
[00:00:14.218,322] <inf> bt_hci_core: HCI transport: SDC
[00:00:14.218,444] <inf> bt_hci_core: Identity: F6:4F:7D:39:A8:A5 (random)
[00:00:14.218,475] <inf> bt_hci_core: HCI: version 6.1 (0x0f) revision 0x1069, manufacturer 0x0059
[00:00:14.218,505] <inf> bt_hci_core: LMP: version 6.1 (0x0f) subver 0x1069
[00:00:14.220,245] <dbg> gopro_discovery: gopro_bt_start: Settings load done
[00:00:14.220,275] <inf> gopro_discovery: Scan module initialized
[00:00:14.220,397] <dbg> gopro_discovery: try_add_address_filter: Saved bond found: C6:D9:69:8A:22:91 (random)
[00:00:14.220,520] <inf> gopro_discovery: Address filter added: C6:D9:69:8A:22:91 (random)
[00:00:14.221,649] <inf> gopro_discovery: Scan started
[00:00:14.221,801] <dbg> canbus_gopro: isotp_rx_thread: Bind ISO-TP
[00:00:14.221,832] <dbg> canbus_gopro: isotp_rx_thread: Semaphore lock 0
[00:00:14.289,154] <dbg> gopro_discovery: scan_filter_match: Filters matched. Address: C6:D9:69:8A:22:91 (random) connectable: 1
[00:00:14.289,245] <dbg> gopro_c: gopro_client_set_sate: Set GoPro state: 2
[00:00:14.289,367] <dbg> gopro_discovery: eir_found: Camera ON, connecting
[00:00:14.354,980] <err> canbus_gopro: Can send timeout
[00:00:14.404,632] <err> canbus_gopro: CAN Sending failed [-11]
[00:00:14.451,782] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)
[00:00:14.451,934] <inf> gopro_discovery: Change security
[00:00:14.452,545] <err> gopro_discovery: Stop LE scan failed (err 0)
[00:00:14.702,911] <wrn> bt_conn: conn 0x200037b0 failed to establish. RF noise?
[00:00:14.703,308] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED
[00:00:14.703,399] <wrn> gopro_discovery: MTU exchange failed (err 14)
[00:00:14.703,613] <inf> gopro_discovery: Disconnected: C6:D9:69:8A:22:91 (random), reason 0x3e 
[00:00:14.703,735] <dbg> gopro_discovery: disconnected: Pause for 3 sec
[00:00:17.703,979] <dbg> gopro_discovery: scan_work_handler: Scan start
[00:00:17.704,132] <dbg> gopro_discovery: try_add_address_filter: Saved bond found: C6:D9:69:8A:22:91 (random)
[00:00:17.704,223] <inf> gopro_discovery: Address filter added: C6:D9:69:8A:22:91 (random)
[00:00:17.705,261] <inf> gopro_discovery: Scan started
[00:00:17.773,529] <dbg> gopro_discovery: eir_found: Camera ON, connecting
[00:00:17.933,135] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)
[00:00:17.933,288] <inf> gopro_discovery: Change security
[00:00:17.933,898] <err> gopro_discovery: Stop LE scan failed (err 0)
[00:00:18.184,265] <wrn> bt_conn: conn 0x200037b0 failed to establish. RF noise?
[00:00:18.184,661] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED
[00:00:18.184,753] <wrn> gopro_discovery: MTU exchange failed (err 14)
[00:00:18.184,967] <inf> gopro_discovery: Disconnected: C6:D9:69:8A:22:91 (random), reason 0x3e 
[00:00:18.185,089] <dbg> gopro_discovery: disconnected: Pause for 3 sec
[00:00:21.185,333] <dbg> gopro_discovery: scan_work_handler: Scan start
[00:00:21.185,485] <dbg> gopro_discovery: try_add_address_filter: Saved bond found: C6:D9:69:8A:22:91 (random)
[00:00:21.185,577] <inf> gopro_discovery: Address filter added: C6:D9:69:8A:22:91 (random)
[00:00:21.186,553] <inf> gopro_discovery: Scan started
[00:00:21.551,940] <dbg> gopro_discovery: eir_found: Camera ON, connecting
[00:00:21.709,045] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)
[00:00:21.709,197] <inf> gopro_discovery: Change security
[00:00:21.709,777] <err> gopro_discovery: Stop LE scan failed (err 0)
[00:00:21.960,174] <wrn> bt_conn: conn 0x200037b0 failed to establish. RF noise?
[00:00:21.960,571] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED
[00:00:21.960,662] <wrn> gopro_discovery: MTU exchange failed (err 14)
[00:00:21.960,845] <inf> gopro_discovery: Disconnected: C6:D9:69:8A:22:91 (random), reason 0x3e 
[00:00:21.960,998] <dbg> gopro_discovery: disconnected: Pause for 3 sec
[00:00:24.961,242] <dbg> gopro_discovery: scan_work_handler: Scan start
[00:00:24.961,395] <dbg> gopro_discovery: try_add_address_filter: Saved bond found: C6:D9:69:8A:22:91 (random)
[00:00:24.961,486] <inf> gopro_discovery: Address filter added: C6:D9:69:8A:22:91 (random)
[00:00:24.962,463] <inf> gopro_discovery: Scan started
[00:00:25.032,592] <dbg> gopro_discovery: eir_found: Camera ON, connecting
[00:00:25.190,948] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)
[00:00:25.191,131] <inf> gopro_discovery: Change security
[00:00:25.191,711] <err> gopro_discovery: Stop LE scan failed (err 0)
[00:00:25.442,077] <wrn> bt_conn: conn 0x200037b0 failed to establish. RF noise?
[00:00:25.442,474] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED
[00:00:25.442,565] <wrn> gopro_discovery: MTU exchange failed (err 14)
[00:00:25.442,779] <inf> gopro_discovery: Disconnected: C6:D9:69:8A:22:91 (random), reason 0x3e 

[00:00:14.220,245] - settings loaded successfully

[00:00:14.220,397] - Saved bond found: C6:D9:69:8A:22:91 (random)

The address is correct, this is my camera. I think we can say that the settings were saved and loaded successfully.

The connection to the camera only starts if the camera is turned on. This is indicated in the advertising ( eir_found function).

To connect, I call the bt_conn_le_create function. In the callback, I display a message that the connection has been established and try to change security level to BT_SECURITY_L2:

static void connected(struct bt_conn *conn, uint8_t conn_err){
	static struct bt_gatt_exchange_params exchange_params;
	char addr[BT_ADDR_LE_STR_LEN];
	int err;

	bt_addr_le_to_str(bt_conn_get_dst(conn), addr, sizeof(addr));

	if (conn_err) {
		LOG_INF("Failed to connect to %s, 0x%02x %s", addr, conn_err, bt_hci_err_to_str(conn_err));

		if (default_conn == conn) {
			bt_conn_unref(default_conn);
			default_conn = NULL;

			(void)k_work_submit(&scan_work);
		}

		return;
	}

	LOG_INF("Connected: %s", addr);
	
	led_idle_timer_start(0);
	gopro_led_mode_set(LED_NUM_REC,LED_MODE_OFF);

	exchange_params.func = exchange_func;
	err = bt_gatt_exchange_mtu(conn, &exchange_params);
	if (err) {
		LOG_WRN("MTU exchange failed (err %d)", err);
	}

	LOG_INF("Change security");
	err = bt_conn_set_security(conn, BT_SECURITY_L2);
	if (err) {
		LOG_WRN("Failed to set security: %d", err);
		gatt_discover(conn);
	}

	err = bt_scan_stop();
	if ((!err) && (err != -EALREADY)) {
		LOG_ERR("Stop LE scan failed (err %d)", err);
	}
}

In debug output:

[00:00:14.451,782] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)
[00:00:14.451,934] <inf> gopro_discovery: Change security
[00:00:14.452,545] <err> gopro_discovery: Stop LE scan failed (err 0)
[00:00:14.702,911] <wrn> bt_conn: conn 0x200037b0 failed to establish. RF noise?
[00:00:14.703,308] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED

If I enter pairing mode on the GoPro, the connection will be successful. And it will be successful many times, even if I disconnect the power. It will connect successfully every time. But after a certain number of connections, or maybe even days, it stops connecting. And it won't connect again, no matter how many times I try, until I enter pairing mode.

By the schematic, my module doesn't have an external 32kHz crystal. Therefore, in the board settings ( https://github.com/Sergey1560/nrf52_gopro_zephyr/blob/master/boards/vend/goprocan_nrf52840/goprocan_nrf52840_defconfig ) , I use:

CONFIG_CLOCK_CONTROL_NRF_K32SRC_SYNTH=y
CONFIG_CLOCK_CONTROL_NRF_K32SRC_XTAL=n

Full device tree:

Wireshark log, when connection fail:

0488.connection_failed.pcapng

What could be the cause of the problem?

[Edvin]

Hello,

If you reset/power cycle the nRF after it fails to connect, will it be able to reconnect as normal then? If not, what does it take for you to be able to connect again? Or do you need to put the gopro in pairing mode for that to work?

From your sniffer trace it looks like the GoPro/peripheral either misses the CONNECT_IND packet at 1685 and 1755, or it is ignored (if the peripheral is using a filter accept list/whitelist). 

Is the GoPro connected to any other devices in the meantime, before it stops working? Is it reset between the two connection attempts in 1685 and 1755 in the sniffer trace?

And a key question, does continue scanning after the failed connection attempt?

I assume you don't have any debug access on your GoPro, right?

Best regards,

Edvin

[D233374]

Edvin said:

If you reset/power cycle the nRF after it fails to connect, will it be able to reconnect as normal then? If not, what does it take for you to be able to connect again? Or do you need to put the gopro in pairing mode for that to work?

I only need to put gopro in pairing mode. Reset/power cycle nRF or GoPro doesn't change anything.

Edvin said:

s the GoPro connected to any other devices in the meantime, before it stops working? Is it reset between the two connection attempts in 1685 and 1755 in the sniffer trace?

I have four devices that connect to my GoPro:
- remote control
- phone
- laptop
- NRF
The problem only occurs with my NRF device.
I debug the device on a table and then test it in the car. Sometimes the connection would work on the table, but then stop working in the car. Between these events, there were no other connections to the GoPro.
I had doubts about the car's power supply, but powering it from a separate battery didn't solve the problem. The interference idea also didn't work—if the NRF stops connecting, it won't connect anywhere else.

No, no other devices connected between these two connection attempts, and the GoPro didn't reboot.

Edvin said:

And a key question, does continue scanning after the failed connection attempt?

I set a 3-second delay between connection attempts to avoid spamming the GoPro. 

As you can see from the debug output, after the connection fails, there is a 3 second pause and then the scanning and connection process starts again. This happens endlessly with the same result.

[00:00:00.549,133] <inf> gopro_discovery: Scan started

[00:00:00.680,175] <dbg> gopro_discovery: scan_filter_match: Filters matched. Address: C6:D9:69:8A:22:91 (random) connectable: 1

[00:00:00.843,566] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)

[00:00:00.843,688] <inf> gopro_discovery: Change security

[00:00:00.844,177] <err> gopro_discovery: Stop LE scan failed (err 0)

[00:00:01.094,787] <wrn> bt_conn: conn 0x200037e0 failed to establish. RF noise?

[00:00:01.095,275] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED

[00:00:01.095,367] <wrn> gopro_discovery: MTU exchange failed (err 14)

[00:00:01.095,520] <inf> gopro_discovery: Disconnected: C6:D9:69:8A:22:91 (random), reason 0x3e

[00:00:01.095,794] <dbg> gopro_discovery: disconnected: Pause for 3 sec

Next attempt:

[00:00:04.096,008] <dbg> gopro_discovery: scan_work_handler: Scan start

[00:00:04.096,130] <dbg> gopro_discovery: try_add_address_filter: Saved bond found: C6:D9:69:8A:22:91 (random)

[00:00:04.096,221] <inf> gopro_discovery: Address filter added: C6:D9:69:8A:22:91 (random)

[00:00:04.097,076] <inf> gopro_discovery: Scan started

[00:00:04.455,474] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)

[00:00:04.455,627] <inf> gopro_discovery: Change security

[00:00:04.456,085] <err> gopro_discovery: Stop LE scan failed (err 0)

[00:00:04.706,542] <wrn> bt_conn: conn 0x200037e0 failed to establish. RF noise?

[00:00:04.706,878] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED

[00:00:04.706,970] <wrn> gopro_discovery: MTU exchange failed (err 14)

[00:00:04.707,153] <inf> gopro_discovery: Disconnected: C6:D9:69:8A:22:91 (random), reason 0x3e

[00:00:04.707,275] <dbg> gopro_discovery: disconnected: Pause for 3 sec

Next attempt:

[00:00:07.707,489] <dbg> gopro_discovery: scan_work_handler: Scan start

[00:00:07.707,611] <dbg> gopro_discovery: try_add_address_filter: Saved bond found: C6:D9:69:8A:22:91 (random)

[00:00:07.707,702] <inf> gopro_discovery: Address filter added: C6:D9:69:8A:22:91 (random)

[00:00:07.708,740] <inf> gopro_discovery: Scan started

[00:00:07.918,243] <dbg> gopro_discovery: eir_found: Camera ON, connecting

[00:00:08.072,906] <inf> gopro_discovery: Connected: C6:D9:69:8A:22:91 (random)

[00:00:08.073,028] <inf> gopro_discovery: Change security

[00:00:08.073,516] <err> gopro_discovery: Stop LE scan failed (err 0)

[00:00:08.324,218] <wrn> bt_conn: conn 0x200037e0 failed to establish. RF noise?

[00:00:08.324,615] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED

[00:00:08.324,707] <wrn> gopro_discovery: MTU exchange failed (err 14)

[00:00:08.324,859] <inf> gopro_discovery: Disconnected: C6:D9:69:8A:22:91 (random), reason 0x3e

[00:00:08.324,981] <dbg> gopro_discovery: disconnected: Pause for 3 sec

Edvin said:

I assume you don't have any debug access on your GoPro, right?

Of course, I don't have access to debugging the GoPro.

[Edvin]

Can you please try to capture a sniffer trace from a successfull connection, and then a new sniffer trace later, when the nRF tries to connect, but is not able to? 

Does the nRF change it's BLE address between these two events? It shouldn't really matter, as long as they are bonded, but it may be a bug in the GoPro FW.

The fact that when this issue first occurs, it doesn't reconnect until the gopro is put in pairing mode again, suggests that it isn't just a packet loss. The GoPro probably dropped the nRF from it's whitelist for some unknown reason. Can you please check the address of the nRF, whether it changes between a working connection and the later stage where it doesn't work?

Best regards,

Edvin

[D233374]

I did the following:
- added creating a static address from hw info and printing the address to debug (bt_id_create() before bt_enable() )
- erased the contents of the NRF flash memory with the saved settings
- erased the connection settings on the GoPro
- recorded a connection dump with pairing
- recorded a successful connection dump
At the moment, the NRF successfully connects to the GoPro. If problems arise again, I can record a connection dump.

Pairing dump:

0636.pairing.pcapng

Successful connection dump:

connection_success.pcapng

[D233374]

I did a little experiment. After pairing and connecting successfully, I changed the NRF address. As expected, the connection failed. But the error was different:

[00:00:01.046,936] <wrn> gopro_discovery: Security failed: C6:EA:FE:77:84:76 (random) level 1 err 2 BT_SECURITY_ERR_PIN_OR_KEY_MISSING

Whereas with the connection problems described in the original message, the error:

[00:00:01.094,787] <wrn> bt_conn: conn 0x200037e0 failed to establish. RF noise?

[00:00:01.095,275] <wrn> gopro_discovery: Security failed: C6:D9:69:8A:22:91 (random) level 1 err 9 BT_SECURITY_ERR_UNSPECIFIED

Perhaps the problem is not in the nRF address.

[Edvin]

If you actively change the address, I would expect it to fail. The question is if the nRF or the GoPro changes address using the same identity, it should be able to detect the address change using the identity resolving key (IRK). But if you set a new random address, that new address would not be resolvable.

Using either the existing connection (or create a new one if you deleted the bonding information of your devices, can you capture a connection while it is still working, and then a new one when it fails?

Best regards,

Edvin

[Edvin]

Also, perhaps reach out to GoPro, and ask if they have seen something similar before? That their devices stops responding to familiar devices at some point.

Best regards,

Edvin