BLE connection error

[Annette]

Development setup:

• 2 x nRF52840 SoC
• Our own PCB’s with inverted F-antenna
• LE PHY 1M
• nRF Connect SDK v1.8.0

Hi,

During testing we experience an issue which seems to be related to the central and peripheral being on the edge of range.

The test setup is a single central and a single peripheral with log output to UART. The distance between the two devices is chosen so the devices continuously connects and disconnects. The central upon connection subscribes to sensor data on several services. The peripheral samples a sensor and notifies the data. Below you find part of the log file. 

15-06-2022 01:57:29.786 [RX] - [18:21:20.569,732] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:35.112 [RX] - [18:21:25.916,4
15-06-2022 01:57:35.128 [RX] - 42] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:37.048 [RX] - [18
15-06-2022 01:57:37.069 [RX] - :21:27.852,996] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:39.260 [RX] - [18:21:30.0
15-06-2022 01:57:39.281 [RX] - 64,605] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:40.904 [RX] - [18:21:31.687,744] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:43.319 [RX] - [18:21:34.122,772]
15-06-2022 01:57:43.335 [RX] -  <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:46.293 [RX] - [18:21:37.077,911] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:49.570 [RX] - [18:21:40.353,759] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:55.071 [RX] - [18:21:45.855,346] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:57.013 [RX] - [18:21:47.797,943] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:57:59.045 [RX] - [18:21:49.84
15-06-2022 01:57:59.066 [RX] - 8,541] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:02.296 [RX] - [18:21:53.080,230] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:04.414 [RX] - [18:21:55.196,685] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:07.435 [RX] - [18:21:58.218,566] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:10.672 [RX] - [18:22:01.454,895] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:13.339 [RX] - [18:22:04.123,199] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:16.058 [RX] - [18:22:06.859,558] <wrn> bt_
15-06-2022 01:58:16.074 [RX] - hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:29.158 [RX] - [18:22:19.961,63
15-06-2022 01:58:29.184 [RX] - 9] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:20.075,714] <wrn> bt_hci_core: opcode 0x200a status 0x09

15-06-2022 01:58:31.196 [RX] - [18:22:21.962,554] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:21.962,829] <wrn> bt_hci_core: opcode 0xfc0e status 0x02
[18:22:22.963,104] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:22.963,348] <wrn> bt_hci_core: opcode 0xfc0e status 0x02

15-06-2022 01:58:33.164 [RX] - [18:22:23.963,623] <wrn> bt_hci_core: o
15-06-2022 01:58:33.200 [RX] - pcode 0xfc0f status 0x02
[18:22:23.963,867] <wrn> bt_hci_core: opcode 0xfc0e status 0x02
[18:22:24.964,172] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:24.964,416] <wrn> bt_hci_core: opcode 0xfc0e status 0x02

15-06-2022 01:58:34.272 [RX] - [18:22:25.
15-06-2022 01:58:34.304 [RX] - 075,836] <err> bt_conn: not connected!
[18:22:25.964,691] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:25.964,935] <wrn> bt_hci_core: opcode 0xfc0e status 0x02

15-06-2022 01:58:36.199 [RX] - [18:22:26.965,240] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:26.965,515] <wrn> bt_hci_core: opcode 0xfc0e status 0x02
[18:22:27.965,789] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:27.966,033] <wrn> bt_hci_core: opcode 0xfc0e status 0x02

The problem is that the central no longer has connection with the peripheral and a power cycle of the central does not help.

The peripheral seems to think that it is in a connection, and therefore does not start advertising again.

Best regards,

Annette

[Hung Bui]

Hi Annette, 

I suspect that the code on the peripheral has crashed and couldn't advertise. 
Could you check there is any assert log  on the peripheral ? You can implement the WDT so that we know for sure if it's the crash on the peripheral causing the issue. 

If you test using one of our sample (e.g peripheral_lbs) do you see the same issue ? 

Could you check which BLE controller you are using ? (Nordic Controller or Zephyr Controller) 

[Annette]

Hi,

Hung Bui said:

Could you check which BLE controller you are using ? (Nordic Controller or Zephyr Controller) 

As I don't have the CONFIG_BT_LL_SW_SPLIT set to yes I assume it is the Nordic Softdevice.

Hung Bui said:

If you test using one of our sample (e.g peripheral_lbs) do you see the same issue ? 

I don't have time for that right now.

Hung Bui said:

Could you check there is any assert log  on the peripheral ?

What do you mean? I get the "<err> bt_conn: not connected!" output.

Hung Bui said:

You can implement the WDT so that we know for sure if it's the crash on the peripheral causing the issue.

The watchdog is active, but doesn't bite.

Other application seems to be still alive.

I  have a new log testing a version where I don't check the tx power after "connection" events to avoid the following output from the old log when it fails:

15-06-2022 01:58:36.199 [RX] - [18:22:26.965,240] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:26.965,515] <wrn> bt_hci_core: opcode 0xfc0e status 0x02
[18:22:27.965,789] <wrn> bt_hci_core: opcode 0xfc0f status 0x02
[18:22:27.966,033] <wrn> bt_hci_core: opcode 0xfc0e status 0x02

In the new test version I have enabled printout of "Connected" and "Disconnected" events from the registered callbacks.

static struct bt_conn_cb conn_callbacks = {
	.connected = connected,
	.disconnected = disconnected,
	.security_changed = security_changed
};
bt_conn_cb_register(&conn_callbacks);

As can be seen below when the fault occurs the "<err> bt_conn: not connected!" is issued as in the old log. I would have assumed that this should result in the "disconnected" callback, but it doesn't occur. Until the fault occurred it had been running for 12 hours shifting between connected/disconnected callbacks as expected.

I can see on LED's that at least two out of three tasks are still alive. In my next test I will enable more printout on UART to verify that the other tasks are alive.

17-06-2022 05:48:24.374 [RX] - [18:00:41.367,401] <wrn> bt_hci_core: opcode 0x200a status 0x09

17-06-2022 05:48:27.461 [RX] - disconnected

17-06-2022 05:48:27.589 [RX] - connected

17-06-2022 05:48:28.581 [RX] - [18:00:45.591,033] <wrn> bt_hci_core: opc
17-06-2022 05:48:28.597 [RX] - ode 0x200a status 0x09

17-06-2022 05:48:31.780 [RX] - disconnected

17-06-2022 05:48:31.893 [RX] - connected

17-06-2022 05:48:32.908 [RX] - [18:00:49.901,733] <wrn> bt_hci_core: opcode 0x200a status 0x09

17-06-2022 05:48:37.403 [RX] - disconnected

17-06-2022 05:48:37.515 [RX] - connected

17-06-2022 05:48:38.507 [RX] - [18:00:55.518,127] <wrn>
17-06-2022 05:48:38.523 [RX] -  bt_hci_core: opcode 0x200a status 0x09

17-06-2022 05:48:39.115 [RX] - disconnected

17-06-2022 05:48:39.435 [RX] - connected

17-06-2022 05:48:40.139 [RX] - disconnected

17-06-2022 05:48:40.427 [RX] - [18:00:57.437,103] <wrn> bt_hci_core: 
17-06-2022 05:48:40.443 [RX] - opcode 0x200a status 0x09

17-06-2022 05:48:41.307 [RX] - connected

17-06-2022 05:48:42.299 [RX] - [18:00:59.307,464] <wrn> bt_hci_core: opcode 0x200a
17-06-2022 05:48:42.315 [RX] -  status 0x09

17-06-2022 05:48:46.810 [RX] - disconnected

17-06-2022 05:48:46.922 [RX] - connected

17-06-2022 05:48:47.914 [RX] - [18:01:04.922,149] <wrn> bt_hci_core: opcode 0x200a s
17-06-2022 05:48:47.930 [RX] - tatus 0x09

17-06-2022 05:48:52.921 [RX] - [18:01:09.922,302] <err> bt_conn: not connected!

I hope to hear from you soon as we have a release on Monday.

Best regards,

Annette

[Hung Bui]

Hi Annette, 

Sorry that i didn't notice the "not connected" error. 
As far as I can see there is only one place that the error is thrown. It's in bt_conn_send_cb() in \zephyr\subsys\bluetooth\host\conn.c .

From what I can see in the code the function is called to send data but if it's not in a connection it won't be able send and will throw the 

-ENOTCONN error. However what worried me is that you didn't receive the disconnected event. 

I think more investigation needed. I will report this internally.
I know it can be difficult but if you can capture a sniffer trace when the issue happens it would be great. Even if you don't capture the last connection if you can capture a normal connect - disconnect session it would also be valuable information. 

I don't think we would come up with a solution before Monday and I will be on a business trip next week. But I will get one of our colleagues to handle your case. 

[Annette]

Hi Hung,

Thank you for your quick answer.

Yes that worries me as well. The device is bricked (no power cycling possible) if it is not either in a connection or advertising. 

I can try to get a sniffer trace.

I don't know if it's relevant, but the code is based on the central_uart and peripheral_uart merged together. 

In the beginning of main() it is detected whether the device is to be a central or a peripheral i.e. if a central it starts scanning and if a peripheral it starts advertising. None of the devices acts as both a peripheral and a central at the same time (scanning AND advertising), but their configuration is the same.

# Enable the UART driver
CONFIG_UART_ASYNC_API=y
CONFIG_NRFX_UARTE0=y
CONFIG_SERIAL=y
CONFIG_UART_0_NRF_PARITY_BIT=y
CONFIG_UART_0_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC_TIMER=1

CONFIG_GPIO=y

# Make sure printk is printing to UART
CONFIG_CONSOLE=y
CONFIG_UART_CONSOLE=y

# Config logger
CONFIG_LOG=y
CONFIG_USE_SEGGER_RTT=n
CONFIG_LOG_BACKEND_UART=y


# BLE TX power
CONFIG_BT_CTLR_TX_PWR_DYNAMIC_CONTROL=y
CONFIG_BT_CTLR_TX_PWR_0=n
CONFIG_BT_CTLR_TX_PWR_PLUS_8=y
CONFIG_BT_CTLR_CONN_RSSI=y

CONFIG_BT_L2CAP_TX_BUF_COUNT=10

# Enable the BLE stack with GATT Client configuration
CONFIG_BT=y
CONFIG_BT_CENTRAL=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_DEVICE_NAME="Sensor"
CONFIG_BT_DEVICE_APPEARANCE=1344
CONFIG_BT_SMP=y
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_GATT_DM_MAX_ATTRS=65

# Enable the NUS service
CONFIG_BT_NUS=n

# Enable the Battery service
CONFIG_BT_BAS=n

# Enable the BLE modules from NCS
CONFIG_BT_NUS_CLIENT=n
CONFIG_BT_BAS_CLIENT=n
CONFIG_BT_SCAN=y
CONFIG_BT_SCAN_FILTER_ENABLE=y
#CONFIG_BT_SCAN_UUID_CNT=1
CONFIG_BT_SCAN_ADDRESS_CNT=1
CONFIG_BT_GATT_DM=y
CONFIG_HEAP_MEM_POOL_SIZE=2048

# This example requires more workqueue stack
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2304

# Enable bonding
CONFIG_BT_SETTINGS=y
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_MAP=y
CONFIG_NVS=y
CONFIG_SETTINGS=y

CONFIG_BT_GAP_AUTO_UPDATE_CONN_PARAMS=y
CONFIG_BT_GAP_PERIPHERAL_PREF_PARAMS=y
CONFIG_BT_PERIPHERAL_PREF_MIN_INT=30
CONFIG_BT_PERIPHERAL_PREF_MAX_INT=40
CONFIG_BT_PERIPHERAL_PREF_LATENCY=0
CONFIG_BT_PERIPHERAL_PREF_TIMEOUT=500

CONFIG_ASSERT=n

# Enable RTC0 for application usage - RTC1 is reserved and used by the Zephyr RTOS kernel timer
CONFIG_NRFX_RTC=y
CONFIG_NRFX_RTC2=y

# Allow for large Bluetooth data packets.
CONFIG_BT_L2CAP_TX_MTU=252
CONFIG_BT_BUF_ACL_RX_SIZE=256

CONFIG_PWM=y
CONFIG_SPI=y
CONFIG_NEWLIB_LIBC=y

# Ensure an MCUboot-compatible binary is generated.
CONFIG_BOOTLOADER_MCUBOOT=y

CONFIG_DFU_TARGET=y
CONFIG_DFU_TARGET_MCUBOOT=y
CONFIG_STREAM_FLASH_ERASE=y
CONFIG_IMG_MANAGER=y
#CONFIG_DFU_TARGET_STREAM_SAVE_PROGRESS=y

CONFIG_DATE_TIME=y
CONFIG_DATE_TIME_NTP=n

#CONFIG_BT_SMP_SC_PAIR_ONLY=y
#CONFIG_BT_SMP_SC_ONLY=y

# Enable NVS
CONFIG_NVS_LOG_LEVEL_DBG=n
CONFIG_MPU_ALLOW_FLASH_WRITE=y

# Enable WDT 
CONFIG_WATCHDOG=y
CONFIG_TASK_WDT=y
CONFIG_TASK_WDT_CHANNELS=8
CONFIG_TASK_WDT_HW_FALLBACK=y
# CONFIG_TASK_WDT_MIN_TIMEOUT should match min wdt timeout of any task 
CONFIG_TASK_WDT_MIN_TIMEOUT=10000 

CONFIG_THREAD_NAME=y 

Number of CONFIG_BT_MAX_CONN has already been set to default value 2 which I assume is due to the configuration of both: CONFIG_BT_CENTRAL=y and CONFIG_BT_PERIPHERAL=y. Enabling the device to be in one connection as a peripheral and another connection as a central.

Could the central/peripheral configuration be what's causing the "<err> bt_conn: not connected!" and the fact that "<wrn> bt_hci_core: opcode 0x200a status 0x09" is issued as can be seen in both the old and the new log.

Just an input of something that could be relevant for you or your colleague.

Best regards,

Annette

[Vidar Berg]

Hi Annette,

Please try to bump CONFIG_BT_MAX_CONN to 3 and see if you are able to replicate the same. It is more of a workaround, but I believe/hope it will fix the problem for now. Status code 0x9 indicates that the connection limit has been exceeded by the way.

Best regards,

Vidar

[Annette]

Hi Vidar,

Vidar Berg said:

Please try to bump CONFIG_BT_MAX_CONN to 3 and see if you are able to replicate the same. It is more of a workaround, but I believe/hope it will fix the problem for now.

If I increment CONFIG_BT_MAX_CONN to 3 wouldn't this cause the central to start scanning again after creating the connection and the peripheral to start advertising again after being connected with?

To monitor if the issue occurs I have added a function to conn.c that returns struct bt_conn->err and struct bt_conn->state. In the application I have created a monitor task that checks the application's against the structbt_conn->state from conn.c if there is an inconsistency between the two for approximately half a minute I let the watchdog bite.

As far as I can see when the issue occurs the struct bt_conn->err is 0, but the struct bt_conn->state is 1 which is BT_CONN_DISCONNECT_COMPLETE. 

Another thing to mention is that the central gets configured with the Bluetooth MAC address of the only peripheral it is allowed to connect with. The address is added to the filter and the filter enabled in the central with bt_scan_filter_add() / bt_scan_filter_enable(). 

Vidar Berg said:

Status code 0x9 indicates that the connection limit has been exceeded by the way.

Is this strange when having the filter enabled?

Best regards,

Annette

[Vidar Berg]

Hi Annette,

CONFIG_BT_MAX_CONN configures the number of concurrent links that shall be supported by the stack, but it is up to the application to decide if it wants to re-start scanning or connectable advertising following a new connection. An example of this is the multilink central sample in Zephyr which only starts scanning if number of connections is less than CONFIG_BT_MAX_CONN as seen here: https://github.com/nrfconnect/sdk-zephyr/blob/d6cd4fc1ceec4bb41c217709c373e5b9ffd05e51/samples/bluetooth/central_multilink/src/central_multilink.c#L159

Also, the opcode that returned 0x9 (connection limit exceeded) was for advertising start

Annette said:

Is this strange when having the filter enabled?

I suspect it may be a race somewhere causing advertising start to get called before the controller's internal state has completed the transition from connected to disconnected. Are you calling advertising start directly from the 'disconnected' callback?

Best regards,

Vidar