NUS connections on nRF Thingy:53 don't work reliably, compared to the nRF5340-DK

[Anthony W]

I am working on firmware that acts as a BLE sensor hub to pipe BLE data from connected sensors to a PC over USB (using the CDC ACM UART interface). The peripheral sensors ship data to the hub via the NUS service. The hub implementation works perfectly on the nRF52840-DK and nRF5340-DK, but when I try to flash the same firmware to the Thingy:53 I run into an issue where the device takes a long time (30s to over a minute) to establish a BLE connection with the sensor, constantly disconnecting with a message saying it couldn't find the NUS service. This doesn't happen on the nRF5340-DK, which I figured should be comparable, or the nRF52840-DK. I looked around at the board configurations for the DK and the Thingy but I didn't see anything glaringly obvious that should affect the performance. I actually would have expected an improvement with the better FEM on the thingy, but that has not been the case.

Any ideas what is going on? The project configuration is here, with the hci_ipc config here.

And below is a sample log. You see after connecting it has GATT issues. In general the BLE connectivity also doesn't seem to be very reliable, on this run when it finally connected it wasn't actually receiving any data, and when I turned the peripheral sensor off it thought it was still connected for at least ten minutes before I turned it off. I should mention that this firmware runs reliably for multiple sensors on custom nRF52832 and nRF52840 devices, as well as the nRF5340-DK, which is maybe why I'm having some trouble tracking down why the Thingy is behaving differently.

SEGGER J-Link V7.94e - Real time terminal output

SEGGER J-Link (unknown) V1.0, SN=1050238983

Process: JLinkExe

*** Booting nRF Connect SDK 3758bcbfa5cd ***

[00:00:00.002,441] <inf> posey_platform: Initializing platform...

[00:00:00.002,441] <inf> posey_platform: Initializing CDC ACM...

[00:00:00.502,655] <inf> posey_platform: Initializing NUS...

[00:00:00.502,655] <inf> posey_nus: Initializing BLE and NUS...

[00:00:00.509,399] <inf> fs_nvs: 8 Sectors of 4096 bytes

[00:00:00.509,399] <inf> fs_nvs: alloc wra: 0, fd0

[00:00:00.509,399] <inf> fs_nvs: data wra: 0, 1c

[00:00:00.525,695] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)

[00:00:00.525,726] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)

[00:00:00.525,756] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870

[00:00:00.526,824] <inf> bt_hci_core: No ID address. App must call settings_load()

[00:00:00.526,824] <inf> posey_nus: Bluetooth initialized

[00:00:00.528,076] <inf> bt_hci_core: Identi[00:00:21.616,241] <inf> posey_task_hub: Connected sensors: 0

[00:00:31.659,454] <inf> posey_task_hub: Connected sensors: 0

[00:00:37.745,178] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:37.745,391] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:37.746,520] <inf> posey_nus: scan_connecting

[00:00:37.853,363] <inf> posey_nus: NordicNUSDriver::connected

[00:00:37.853,515] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:37.853,546] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:37.853,637] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:37.853,637] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:37.853,668] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:37.853,729] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:38.054,504] <inf> posey_nus: MTU exchange done

[00:00:38.703,918] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:38.954,376] <inf> posey_nus: NUS service discovery completed.

[00:00:38.954,559] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:38.954,559] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:41.698,547] <inf> posey_task_hub: Connected sensors: 1

[00:00:42.754,364] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:42.754,547] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:42.754,577] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:42.754,577] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:42.755,065] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:42.760,070] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:42.760,253] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:42.761,840] <inf> posey_nus: scan_connecting

[00:00:42.975,219] <inf> posey_nus: NordicNUSDriver::connected

[00:00:42.975,372] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:42.975,433] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:42.975,524] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:42.975,524] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:42.975,555] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:42.975,616] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:43.176,361] <inf> posey_nus: MTU exchange done

[00:00:43.775,756] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:44.076,232] <inf> posey_nus: NUS service discovery completed.

[00:00:44.076,416] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:44.076,416] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:44.276,214] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:44.276,397] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:44.276,428] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:44.276,428] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:44.276,947] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:44.283,325] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:44.283,508] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:44.285,064] <inf> posey_nus: scan_connecting

[00:00:44.495,849] <inf> posey_nus: NordicNUSDriver::connected

[00:00:44.496,002] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:44.496,063] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:44.496,154] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:44.496,154] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:44.496,185] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:44.496,246] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:44.897,003] <inf> posey_nus: MTU exchange done

[00:00:45.096,801] <inf> posey_nus: NUS service discovery completed.

[00:00:45.096,832] <err> nus_c: Missing NUS TX characteristic.

[00:00:45.096,832] <err> nus_c: Subscribe failed (err -128)

[00:00:45.096,862] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:45.096,893] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:45.097,991] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:45.098,205] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:45.098,205] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:45.098,205] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:45.098,693] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:45.529,907] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:45.530,120] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:45.531,677] <inf> posey_nus: scan_connecting

[00:00:45.846,221] <inf> posey_nus: NordicNUSDriver::connected

[00:00:45.846,374] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:45.846,435] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:45.846,496] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:45.846,527] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:45.846,557] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:45.846,588] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:46.047,363] <inf> posey_nus: MTU exchange done

[00:00:46.597,167] <err> bt_gatt_dm: Characteristic discover failed, error: -128.

[00:00:46.597,229] <wrn> posey_nus: Error while discovering GATT service: (-128 - )

[00:00:46.597,320] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:46.597,534] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:46.597,564] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:46.597,564] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:46.597,595] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:46.610,626] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:46.610,809] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:46.612,396] <inf> posey_nus: scan_connecting

[00:00:46.717,254] <inf> posey_nus: NordicNUSDriver::connected

[00:00:46.717,437] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:46.717,468] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:46.717,559] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:46.717,559] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:46.717,590] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:46.717,651] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:47.018,402] <inf> posey_nus: MTU exchange done

[00:00:47.567,810] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:47.718,200] <inf> posey_nus: NUS service discovery completed.

[00:00:47.718,231] <err> nus_c: Missing NUS TX characteristic.

[00:00:47.718,231] <err> nus_c: Subscribe failed (err -128)

[00:00:47.718,261] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:47.718,261] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:47.719,329] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:47.719,543] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:47.719,543] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:47.719,543] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:47.720,062] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:50.871,154] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:50.871,368] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:50.872,924] <inf> posey_nus: scan_connecting

[00:00:50.982,574] <inf> posey_nus: NordicNUSDriver::connected

[00:00:50.982,727] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:50.982,788] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:50.982,849] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:50.982,879] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:50.982,910] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:50.982,940] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:51.183,715] <inf> posey_nus: MTU exchange done

[00:00:51.738,464] <inf> posey_task_hub: Connected sensors: 1

[00:00:51.883,361] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:51.883,666] <err> bt_gatt_dm: Characteristic discover failed, error: -128.

[00:00:51.883,728] <wrn> posey_nus: Error while discovering GATT service: (-128 - )

[00:00:51.883,819] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:51.884,002] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:51.884,002] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:51.884,033] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:51.884,033] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:51.894,226] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:51.894,439] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:51.895,996] <inf> posey_nus: scan_connecting

[00:00:52.004,302] <inf> posey_nus: NordicNUSDriver::connected

[00:00:52.004,455] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:52.004,486] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:52.004,577] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:52.004,577] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:52.004,608] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:52.004,669] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:52.255,432] <inf> posey_nus: MTU exchange done

[00:00:52.804,809] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:53.055,297] <inf> posey_nus: NUS service discovery completed.

[00:00:53.055,480] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:53.055,480] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:53.160,552] <inf> posey_nus: Slot 0 bandwidth: 12797 B in 14.10s - 0.89 KBps

[00:00:53.405,303] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:53.405,517] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:53.405,517] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:53.405,517] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:53.406,036] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:53.418,060] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:53.418,243] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:53.419,616] <inf> posey_nus: scan_connecting

[00:00:54.966,156] <inf> posey_nus: NordicNUSDriver::connected

[00:00:54.966,308] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:54.966,369] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:54.966,430] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:54.966,461] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:54.966,491] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:54.966,522] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:55.167,266] <inf> posey_nus: MTU exchange done

[00:00:55.766,693] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:55.867,065] <err> bt_gatt_dm: Characteristic discover failed, error: -128.

[00:00:55.867,126] <wrn> posey_nus: Error while discovering GATT service: (-128 - )

[00:00:55.867,218] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:55.867,401] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:55.867,431] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:55.867,431] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:55.867,431] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:56.194,580] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:56.194,763] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:56.196,319] <inf> posey_nus: scan_connecting

[00:00:56.507,629] <inf> posey_nus: NordicNUSDriver::connected

[00:00:56.507,781] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:56.507,843] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:56.507,904] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:56.507,934] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:56.507,965] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:56.507,995] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:56.708,831] <inf> posey_nus: MTU exchange done

[00:00:57.308,410] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:57.308,715] <err> bt_gatt_dm: Characteristic discover failed, error: -128.

[00:00:57.308,776] <wrn> posey_nus: Error while discovering GATT service: (-128 - )

[00:00:57.308,868] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:57.309,051] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

[00:00:57.309,051] <inf> posey_nus: 0 of 4 sensors connected.

[00:00:57.309,082] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:57.309,082] <inf> posey_nus: BLE scanning: Connected to 0 sensors. Active scanning.

[00:00:57.743,408] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:57.743,621] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connectable: 1

[00:00:57.745,178] <inf> posey_nus: scan_connecting

[00:00:57.850,830] <inf> posey_nus: NordicNUSDriver::connected

[00:00:57.850,982] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:57.851,043] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:57.851,104] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:57.851,135] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:57.851,165] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:57.851,226] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:58.301,971] <inf> posey_nus: MTU exchange done

[00:00:58.851,379] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:59.101,837] <inf> posey_nus: NUS service discovery completed.

[00:00:59.102,020] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:59.102,020] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:59.256,774] <inf> posey_nus: Slot 0 bandwidth: 488 B in 6.10s - 0.08 KBps

[00:01:01.781,066] <inf> posey_task_hub: Connected sensors: 1

[00:01:11.823,089] <inf> posey_task_hub: Connected sensors: 1

[00:01:21.864,715] <inf> posey_task_hub: Connected sensors: 1

[00:01:31.906,951] <inf> posey_task_hub: Connected sensors: 1

[00:01:41.948,699] <inf> posey_task_hub: Connected sensors: 1

[00:01:51.991,638] <inf> posey_task_hub: Connected sensors: 1

[00:02:02.033,355] <inf> posey_task_hub: Connected sensors: 1

[00:02:12.075,256] <inf> posey_task_hub: Connected sensors: 1

[00:02:22.117,675] <inf> posey_task_hub: Connected sensors: 1

[00:02:32.161,804] <inf> posey_task_hub: Connected sensors: 1

[Sigurd]

Hi!

[00:00:38.954,559] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:41.698,547] <inf> posey_task_hub: Connected sensors: 1

[00:00:42.754,364] <inf> posey_nus: NordicNUSDriver::disconnected

[00:00:42.754,547] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 13 - Unknown)

1) Would you be able to capture a sniffer trace of these disconnects you are seeing? Would be interesting to see what's happening on-air as well. https://www.nordicsemi.com/Products/Development-tools/nrf-sniffer-for-bluetooth-le

2) The problem seem to come after you have connected to 1 sensor, and then start scanning for more for sensors.

What happens if you only connect to 1 sensor, and don't try to connect to any more sensors, is the connection stable then?

If yes, then please check the connection interval you are using for, and that the scanning has a reasonable scan interval/window, that leaves room for the connections as well.

[Anthony W]

This was extremely helpful. I don't have a sniffer log because it seems I was able to fix it based on part 2 alone. Previously, I would directly re-enable scanning at the end of the GATT discovery complete callback. Now, anywhere I restart scanning, I add it to the work queue instead, based on what I saw in the peripheral_hr_coded example. This seems to have resolved the GATT issues completely.

However, one odd thing that's happening now is that, at least with multiple sensors connected, it seems to fail to execute all of the BLE callbacks. What I observe happening is something like this example:

1. Device is turned on. No sensors connected.

2. Power on sensor. Device connects, I see full bandwidth (~7KB/s)

3. Power on second sensor. Device connects, one sensor drops bandwidth, the other is close to full (~3KB/s for one, 7KB/s for the other).

4. At this point, powering down either device doesn't result in a disconnect callback. The central hub firmware still thinks they're connected. Powering them on again also doesn't cause a reconnect.

Sometimes, the device with full bandwidth will still see a disconnect event, and I can even reconnect it. The device that has the reduced bandwidth never sees the event. This behavior, by the way, was observed previously on the nRF5340 (not a result of these changes). I do not see it on the nRF52840 so, perhaps like this bug, there might just be extra synchronization required somewhere to account for the fact the BLE host and controller are on different cores.

I attached a trace and a log as an example of this. I connect one sensor, it works fine. I attach another, it connects, but you see a drop in bandwidth on one. I can disconnect the first sensor, which yields no disconnect event, you just see the bandwidth drops to zero. The second sensor I'm able to disconnect and reconnect again. But the second time I power it down, there's also no disconnect event. There seems to be a disconnect somewhere, but I'm not sure where. Any further ideas? I can also open a new ticket if that's helpful, since this seems like a different (but similar) synchronization bug.

Here's the sniffer trace. I only went as far as to figure out how to capture it, so I have no idea if it contains anything useful.

SEGGER J-Link V7.94e - Real time terminal output

SEGGER J-Link (unknown) V1.0, SN=1050009132

Process: JLinkExe

*** Booting nRF Connect SDK v3.5.99-ncs1-1 ***

[00:00:00.002,441] <inf> posey_platform: Initializing platform...

[00:00:00.002,441] <inf> posey_platform: Initializing CDC ACM...

[00:00:00.502,624] <inf> posey_platform: Initializing NUS...

[00:00:00.502,624] <inf> posey_nus: Initializing BLE and NUS...

[00:00:00.509,399] <inf> fs_nvs: 8 Sectors of 4096 bytes

[00:00:00.509,399] <inf> fs_nvs: alloc wra: 0, fd0

[00:00:00.509,399] <inf> fs_nvs: data wra: 0, 1c

[00:00:00.525,665] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)

[00:00:00.525,695] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)

[00:00:00.525,726] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 54.58864 Build 1214809870

[00:00:00.526,794] <inf> bt_hci_core: No ID address. App must call settings_load()

[00:00:00.526,794] <inf> posey_nus: Bluetooth initialized

[00:00:00.528,045] <inf> bt_0m

[0m

[0m

[00:00:11.576,843] <inf> posey_task_hub: Connected sensors: 0

[00:00:17.090,728] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:17.090,911] <inf> posey_nus: Filters matched. Name: Posey r2405 Rose (slot 0) Address: DE:AD:DC:19:58:5E (random) connect

able: 1

[00:00:17.092,285] <inf> posey_nus: scan_connecting

[00:00:17.309,631] <inf> posey_nus: NordicNUSDriver::connected

[00:00:17.309,814] <inf> posey_nus: Name: Posey r2405 Rose

[00:00:17.309,844] <inf> posey_nus: Connected to Posey r2405 Rose at DE:AD:DC:19:58:5E (random)

[00:00:17.309,936] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:17.309,936] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:17.309,967] <inf> posey_nus: Running NUS discovery for Posey r2405 Rose

[00:00:17.310,028] <inf> posey_nus: 1 of 4 sensors connected.

[00:00:17.510,803] <inf> posey_nus: MTU exchange done

[00:00:18.160,186] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:18.460,662] <inf> posey_nus: NUS service discovery completed.

[00:00:18.461,029] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:18.461,029] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:00:21.619,232] <inf> posey_task_hub: Connected sensors: 1

[00:00:22.321,441] <inf> posey_nus: Connection parameters update request received.

[00:00:22.321,441] <inf> posey_nus: - Connection interval: [24, 40]

[00:00:22.321,441] <inf> posey_nus: - Latency: 0

[00:00:22.321,472] <inf> posey_nus: - Timeout: 42

[00:00:22.652,618] <inf> posey_nus: Connection parameters updated:

[00:00:22.652,648] <inf> posey_nus: - Interval: 40; Latency: 0; Timeout: 42

[00:00:23.570,678] <inf> posey_nus: Slot 3 bandwidth: 36075 B in 5.01s - 7.04 KBps

[00:00:28.615,447] <inf> posey_nus: Slot 3 bandwidth: 35831 B in 5.05s - 6.94 KBps

[00:00:31.485,778] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:00:31.485,992] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connect

able: 1

[00:00:31.487,243] <inf> posey_nus: scan_connecting

[00:00:31.660,888] <inf> posey_task_hub: Connected sensors: 1

[00:00:31.802,459] <inf> posey_nus: NordicNUSDriver::connected

[00:00:31.802,612] <inf> posey_nus: Name: Posey r2405 Lily

[00:00:31.802,673] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:00:31.802,734] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:31.802,764] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:00:31.802,795] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:00:31.802,856] <inf> posey_nus: 2 of 4 sensors connected.

[00:00:31.968,353] <inf> posey_nus: MTU exchange done

[00:00:32.718,353] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:00:32.818,389] <inf> posey_nus: NUS service discovery completed.

[00:00:32.818,756] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:00:32.818,756] <inf> posey_nus: BLE scanning: Connected to 2 sensors. Active scanning.

[00:00:33.714,324] <inf> posey_nus: Slot 3 bandwidth: 29836 B in 5.10s - 5.71 KBps

[00:00:36.818,237] <inf> posey_nus: Connection parameters update request received.

[00:00:36.818,267] <inf> posey_nus: - Connection interval: [24, 40]

[00:00:36.818,267] <inf> posey_nus: - Latency: 0

[00:00:36.818,298] <inf> posey_nus: - Timeout: 42

[00:00:37.073,638] <inf> posey_nus: Connection parameters updated:

[00:00:37.073,669] <inf> posey_nus: - Interval: 40; Latency: 0; Timeout: 42

[00:00:37.972,961] <inf> posey_nus: Slot 0 bandwidth: 36075 B in 5.05s - 6.98 KBps

[00:00:38.765,747] <inf> posey_nus: Slot 3 bandwidth: 19937 B in 5.05s - 3.85 KBps

[00:00:41.701,507] <inf> posey_task_hub: Connected sensors: 2

[00:00:42.974,060] <inf> posey_nus: Slot 0 bandwidth: 35587 B in 5.00s - 6.95 KBps

[00:00:43.810,791] <inf> posey_nus: Slot 3 bandwidth: 19449 B in 5.05s - 3.76 KBps

[00:00:47.978,118] <inf> posey_nus: Slot 0 bandwidth: 36319 B in 5.00s - 7.09 KBps

[00:00:48.816,223] <inf> posey_nus: Slot 3 bandwidth: 20042 B in 5.01s - 3.91 KBps

[00:00:51.744,934] <inf> posey_task_hub: Connected sensors: 2

[00:00:53.019,989] <inf> posey_nus: Slot 0 bandwidth: 33496 B in 5.04s - 6.49 KBps

[00:00:58.070,465] <inf> posey_nus: Slot 0 bandwidth: 36458 B in 5.05s - 7.05 KBps

[00:01:01.786,834] <inf> posey_task_hub: Connected sensors: 2

[00:01:02.718,292] <inf> posey_nus: NordicNUSDriver::disconnected

[00:01:02.718,475] <wrn> posey_nus: Disconnected from Posey r2405 Lily at D6:81:5C:04:F1:2E (random) (reason: 8 - Connection tim

eout)

[00:01:02.718,505] <inf> posey_nus: 1 of 4 sensors connected.

[00:01:02.718,536] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:01:02.718,994] <inf> posey_nus: BLE scanning: Connected to 1 sensors. Active scanning.

[00:01:11.829,101] <inf> posey_task_hub: Connected sensors: 1

[00:01:16.342,895] <inf> posey_nus: NordicNUSDriver::scan_filter_match

[00:01:16.343,078] <inf> posey_nus: Filters matched. Name: Posey r2405 Lily (slot 1) Address: D6:81:5C:04:F1:2E (random) connect

able: 1

[00:01:16.344,635] <inf> posey_nus: scan_connecting

[00:01:16.555,969] <inf> posey_nus: NordicNUSDriver::connected

[00:01:16.556,121] <inf> posey_nus: Name: Posey r2405 Lily

[00:01:16.556,182] <inf> posey_nus: Connected to Posey r2405 Lily at D6:81:5C:04:F1:2E (random)

[00:01:16.556,243] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:01:16.556,274] <inf> posey_nus: NordicNUSDriver::gatt_discover

[00:01:16.556,304] <inf> posey_nus: Running NUS discovery for Posey r2405 Lily

[00:01:16.556,365] <inf> posey_nus: 2 of 4 sensors connected.

[00:01:16.668,365] <inf> posey_nus: MTU exchange done

[00:01:17.367,614] <inf> posey_nus: LE PHY updated: TX PHY LE 2M, RX PHY LE 2M

[00:01:17.568,176] <inf> posey_nus: NUS service discovery completed.

[00:01:17.568,511] <inf> posey_nus: NordicNUSDriver::scan_stop

[00:01:17.568,542] <inf> posey_nus: BLE scanning: Connected to 2 sensors. Active scanning.

[00:01:17.723,358] <inf> posey_nus: Slot 0 bandwidth: 31300 B in 19.65s - 1.56 KBps

[00:01:21.577,575] <inf> posey_nus: Connection parameters update request received.

[00:01:21.577,575] <inf> posey_nus: - Connection interval: [24, 40]

[00:01:21.577,575] <inf> posey_nus: - Latency: 0

[00:01:21.577,606] <inf> posey_nus: - Timeout: 42

[00:01:21.873,748] <inf> posey_task_hub: Connected sensors: 2

[00:01:21.901,855] <inf> posey_nus: Connection parameters updated:

[00:01:21.901,885] <inf> posey_nus: - Interval: 40; Latency: 0; Timeout: 42

[00:01:22.725,311] <inf> posey_nus: Slot 0 bandwidth: 34716 B in 5.00s - 6.78 KBps

[00:01:27.871,948] <inf> posey_nus: Slot 0 bandwidth: 36075 B in 5.15s - 6.85 KBps

[00:01:31.915,252] <inf> posey_task_hub: Connected sensors: 2

[00:01:32.873,718] <inf> posey_nus: Slot 0 bandwidth: 36702 B in 5.00s - 7.17 KBps

[00:01:37.919,982] <inf> posey_nus: Slot 0 bandwidth: 35448 B in 5.05s - 6.86 KBps

[00:01:41.957,733] <inf> posey_task_hub: Connected sensors: 2

[00:01:51.999,633] <inf> posey_task_hub: Connected sensors: 2

[00:02:02.041,870] <inf> posey_task_hub: Connected sensors: 2

[00:02:12.085,052] <inf> posey_task_hub: Connected sensors: 2

[00:02:22.127,960] <inf> posey_task_hub: Connected sensors: 2

[00:02:32.171,539] <inf> posey_task_hub: Connected sensors: 2

[00:02:42.214,172] <inf> posey_task_hub: Connected sensors: 2

[00:02:52.256,591] <inf> posey_task_hub: Connected sensors: 2

[00:03:02.298,706] <inf> posey_task_hub: Connected sensors: 2

[00:03:12.341,674] <inf> posey_task_hub: Connected sensors: 2

[00:03:22.385,040] <inf> posey_task_hub: Connected sensors: 2

[00:03:32.427,886] <inf> posey_task_hub: Connected sensors: 2

[00:03:42.470,825] <inf> posey_task_hub: Connected sensors: 2

[00:03:52.513,885] <inf> posey_task_hub: Connected sensors: 2

[00:04:02.556,793] <inf> posey_task_hub: Connected sensors: 2

[00:04:12.599,945] <inf> posey_task_hub: Connected sensors: 2

[00:04:22.643,310] <inf> posey_task_hub: Connected sensors: 2

[00:04:32.685,638] <inf> posey_task_hub: Connected sensors: 2

[Anthony W]

A different question but maybe a bit easier to answer: what considerations should be made for moving code from the nRF52 series to the dual core nRF53? Are the best practices or common "gotchas" to look out for? To me this seems like a strange bug to have, but maybe the NUS client library does not support multiple clients well in the two core setup, or I need to make some modification. Any advice you have to track down the source of the problem would also be helpful, the BLE software stack is difficult to sift through.