Trouble Reconnecting Peripherals after Disconnection.

[siltvm]

Hi,

We are developing a new project using the nRF52832 as our controller and nRF5 SDK 17.0.2 as our SDK.

We have integrated the NUS client and NUS peripheral parts from the ble_app_uart_c and ble_app_uart example projects. We've checked the functionality and it works well in the first stage. That is, the device can scan for nearby advertised devices based on the NUS service and connect to them. After the connection, the device acts as a peripheral and can connect with the nRF Connect app, sending and receiving data to and from the app through the connected device. Essentially, the device acts as a gateway between the app and connected peripherals.

Initially, there was no issue with the BLE connection. However, after disconnecting the nearby advertised peripherals, we are unable to connect to the two peripherals again. We can only connect to the same peripheral. What could be the issue?

Device (gateway acting as central and peripheral): NUS client and NUS peripheral integrated ble_app_hrs_rscs_relay example code flashed board . Connected peripheral: Modified NUS client and NUS peripheral integrated ble_app_hrs_rscs_relay example code flashed board , capable of capturing nearby beacon data and sending it to the connected gateway.

When we initially flash the code, we can connect the gateway to two nearby peripherals. However, when a peripheral disconnects, we can't connect to that two peripheral again.but we can connect only one same peripherl . The log output shows this:

SCAN START

12:13:07.819 -> <info> app: Connected to target F0C798AA5E92

12:13:07.819 -> <info> app: Central connected

12:13:07.819 -> <info> app: Attempt to find HRS, RSC, or NUS conn_handle 0x0

12:13:07.819 -> <info> app: NUS client assigned to conn_handle 0x0 (index: 0)

12:13:07.866 -> <info> app: nrf_ble_scan_start : 0
12:13:07.866 -> 

12:13:07.866 -> <info> app: SCAN START

12:13:08.287 -> <info> app: ATT MTU exchange completed.

12:13:08.334 -> <info> app: Ble NUS max data length set to 0xF4(244)

12:13:08.334 -> <info> peer_manager_handler: Connection security failed: role: Central, conn_handle: 0x0, procedure: Bonding, error: 133

12:13:08.334 -> <warning> peer_manager_handler: Disconnecting conn_handle 0.

12:13:08.475 -> <error> nrf_ble_gq: SD GATT procedure (3) failed on connection handle 0 with error: 0x00000008.

12:13:08.475 -> <info> app: DB Discovery instance 0x2000477C available on conn handle: 0

12:13:08.522 -> <info> app: Found 1 services on conn_handle: 0

12:13:08.522 -> <info> app: current instance index 0
12:13:08.522 -> 

12:13:08.522 -> <info> app: Disconnected from instance 0

12:13:08.522 -> <info> app: nrf_ble_scan_start : 0
12:13:08.522 -> 

12:13:08.522 -> <info> app: SCAN START

12:13:08.522 -> <info> app: Device disconnected, conn_handle: 0x0, reason: 0x16

12:13:08.522 -> <info> app: nrf_ble_scan_start : 0
12:13:08.522 -> 

12:13:08.522 -> <info> app: SCAN START

12:13:09.646 -> <info> app: Connected to target F0C798AA5E92

12:13:09.646 -> <info> app: Central connected

12:13:09.646 -> <info> app: Attempt to find HRS, RSC, or NUS conn_handle 0x0

12:13:09.646 -> <info> app: NUS client assigned to conn_handle 0x0 (index: 0)

12:13:09.646 -> <info> app: nrf_ble_scan_start : 0
12:13:09.646 -> 

12:13:09.646 -> <info> app: SCAN START

12:13:10.256 -> <info> app: ATT MTU exchange completed.

12:13:10.303 -> <info> app: Ble NUS max data length set to 0xF4(244)

12:13:10.443 -> <info> peer_manager_handler: Connection security failed: role: Central, conn_handle: 0x0, procedure: Bonding, error: 133

12:13:10.490 -> <warning> peer_manager_handler: Disconnecting conn_handle 0.

12:13:10.678 -> <error> nrf_ble_gq: SD GATT procedure (3) failed on connection handle 0 with error: 0x00000008.

12:13:10.678 -> <info> app: DB Discovery instance 0x2000477C available on conn handle: 0

12:13:10.678 -> <info> app: Found 1 services on conn_handle: 0

12:13:10.678 -> <info> app: current instance index 0
12:13:10.678 -> 

12:13:10.678 -> <info> app: Disconnected from instance 0

kindly Please provide your response as soon as possible. Your valuable input is urgently needed. 

[Hung Bui]

Hi,

Have you read my first reply ? 
If you look at the log you can find this: 
12:13:10.443 -> <info> peer_manager_handler: Connection security failed: role: Central, conn_handle: 0x0, procedure: Bonding, error: 133

Error 133 is BLE_GAP_SEC_STATUS_PAIRING_NOT_SUPP. So either the central or the peripheral has responded that pairing is not supported. 

You can test by disabling bonding and see if the issue still occurs. 

If it stops, we need to look into which device causing the issue, a sniffer trace can help here. 
Have you made sure you connect to the correct device not other random device around ? 
How did you recover from the situation, how did you connect to the 2 devices that you couldn't connect ? 

What you can do is to turn off any device that you still can connect and leave only the device that you can not connect. Try to use the log to see if the central can scan for the advertising packet and check if it can send connect request, then sniffer trace to capture the communication. 

Pay attention to the log 12:13:08.334 -> <info> peer_manager_handler: Connection security failed:  to see if it occurs when testing

[siltvm]

 Hung Bui , 

I just removed the bonding parts from peripheral as well as central in peer manager initializations, so there are no errors like security failures currently present.

If I turn off the device that I can able to connect to, then the device that couldn't connect can able to connect into the gateway. That is actually a little bit more confusing part.

That is, if I have two devices, Device 1 and Device 2. Assume that Device 1 connects first, then Device 2 connects secondly into the gateway. If I am disconnecting the two devices and then powering them again, I can able to connect only the first connected device (Device 1), the second connected device (Device 2) couldn't able to connect to the gateway. If I am powering off the firstly connected peripheral, then there is only Device 2 advertising during this time, and the gateway can able to connect into Device 2.

What is happening here? What could be the reason for the issue?

[Hung Bui]

Hi, 

Thanks for more info. 
Now we will need to debug this step by step. After you get the device 1 re-connected you couldn't connect to Device 2. We will need to check why it couldn't connect to Device 2. 

1. Check if it can scan for device 2 advertising packet 

2. If it can scan for device 2 advertising packet, we will need to check if it send the connect request to device 2 or if there is any error that the code doesn't call the connection function, or if the connect function is called but the actual radio packet is not sent. 

3. If it can not scan for device 2 advertising packet , we will need to check why. If device 2 actually send anything or if for some reason the central can't scan. We will need to check if it scan for other device (not Device 1 or 2) 

 CURRENT ROLE : 00 means that the device is scanning not in peripheral or central role. 

I suspect there could be an issue with the total link count, please try to increase the following: 
NRF_SDH_BLE_TOTAL_LINK_COUNT

NRF_SDH_BLE_CENTRAL_LINK_COUNT

NRF_SDH_BLE_PERIPHERAL_LINK_COUNT

This is just to test to narrow down the issue. Please try to increase these setting in sdk_config.h by at least one. 

[siltvm]

Hung Bui

When I am checking the NRF log for further clarification, I observed that when Device 1 connected, there are some events that happened inside the peer_manager_event_handler. These are:

12:02:59.010 -> <info> app: ENTER PM EVENT HANDLER: evt_id=5
12:02:59.010 -> <info> app: ENTER PM EVENT HANDLER: evt_id=1
12:02:59.010 -> <info> app: ENTER PM EVENT HANDLER: evt_id=5

But if Device 2 is connected, these events do not happen. Is my bonding removal in the gateway code not properly done ?.

I will attach my log console output.

Here, my Device 1 MAC ID is E81D0E54B577,

Device 2 MAC ID is D37CF00CAD14,

the NRF Connect apk installed phone MAC ID is 7E50F95DCE9F.

12:02:55.495 -> <info> app_timer: RTC: initialized.

12:02:55.495 -> <info> app: nrf_sdh_enable_request : 0
12:02:55.495 -> 

12:02:55.495 -> <info> app: nrf_sdh_ble_default_cfg_set : 0
12:02:55.495 -> 

12:02:55.495 -> <info> app: nrf_sdh_ble_enable : 0
12:02:55.495 -> 

12:02:55.495 -> <info> app:  after nrf sdh ble observer 
12:02:55.495 -> 

12:02:55.495 -> <info> app: nrf_ble_scan_init : 0
12:02:55.495 -> 

12:02:55.495 -> <info> app: scan filter init HART_RATE_SERVICE_UUID_IDX : 0
12:02:55.495 -> 

12:02:55.495 -> <info> app: scan filter init RSCS_SERVICE_UUID_IDX : 0
12:02:55.495 -> 

12:02:55.495 -> <info> app: scan filter init NUS : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: nrf_ble_scan_filters_enable : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: nrf_ble_gatt_init : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: nrf_ble_gatt_att_mtu_central_set : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: nrf_ble_gatt_att_mtu_periph_set : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: ble_db_discovery_init :0
12:02:55.542 -> 

12:02:55.542 -> <info> app: ble_hrs_c_init : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: ble_rscs_c_init : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: ble_nus_c_init for instance 0: 0

12:02:55.542 -> <info> app: ble_nus_c_init for instance 1: 0

12:02:55.542 -> <info> app: nrf_ble_qwr_init : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: nrf_ble_qwr_init : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: nrf_ble_qwr_init : 0
12:02:55.542 -> 

12:02:55.542 -> <info> app: ble_hrs_init : 0
12:02:55.588 -> 

12:02:55.588 -> <info> app: ble_rscs_init : 0
12:02:55.588 ->  

12:02:55.588 -> <info> app:  ble_nus_init : 0
12:02:55.588 -> 

12:02:55.588 -> <info> app: Relay example started.

12:02:55.588 -> <info> app: ADV_SCAN_START

12:02:55.588 -> <info> app: nrf_ble_scan_start : 0
12:02:55.588 -> 

12:02:55.588 -> <info> app: SCAN START

12:02:55.588 -> <info> app: Fast advertising.

12:02:57.276 -> <info> app: Connected to target E81D0E54B577

12:02:57.276 -> <info> app: Central connected

12:02:57.276 -> <info> app: Attempt to find HRS, RSC, or NUS conn_handle 0x0

12:02:57.276 -> <info> app: NUS client assigned to conn_handle 0x0 (index: 0)

12:02:57.276 -> <info> app: nrf_ble_scan_start : 0
12:02:57.276 -> 

12:02:57.276 -> <info> app: SCAN START

12:02:57.322 -> <info> app: ATT MTU exchange completed.

12:02:57.322 -> <info> app: Ble NUS max data length set to 0xF4(244)

12:02:59.010 -> <info> app: HRS discovered on conn_handle 0x0

12:02:59.010 -> <info> app: ENTER PM EVENT HANDLER: evt_id=5

12:02:59.010 -> <info> app: ENTER PM EVENT HANDLER: evt_id=1

12:02:59.010 -> <info> app: Running Speed and Cadence service discovered on conn_handle 0x0

12:02:59.010 -> <info> app: ENTER PM EVENT HANDLER: evt_id=5

12:02:59.010 -> <info> app: current instance index 0
12:02:59.010 -> 

12:02:59.010 -> <info> app: Discovery complete ble_nus_c_evt_handler

12:02:59.010 -> <info> app: Connected to device with Nordic UART Service.

12:02:59.056 -> <info> app: DB Discovery instance 0x2000477C available on conn handle: 0

12:02:59.056 -> <info> app: Found 3 services on conn_handle: 0

12:03:00.041 -> <info> app: Connected to target D37CF00CAD14

12:03:00.041 -> <info> app: Central connected

12:03:00.041 -> <info> app: Attempt to find HRS, RSC, or NUS conn_handle 0x1

12:03:00.087 -> <info> app: NUS client assigned to conn_handle 0x1 (index: 1)

12:03:00.275 -> <info> app: ATT MTU exchange completed.

12:03:00.275 -> <info> app: Ble NUS max data length set to 0xF4(244)

12:03:01.915 -> <info> app: current instance index 1
12:03:01.915 -> 

12:03:01.915 -> <info> app: Discovery complete ble_nus_c_evt_handler

12:03:01.915 -> <info> app: Connected to device with Nordic UART Service.

12:03:01.915 -> <info> app: DB Discovery instance 0x20004D4C available on conn handle: 1

12:03:01.915 -> <info> app: Found 3 services on conn_handle: 1

12:05:55.299 -> <info> app: Fast advertising.

12:05:55.299 -> <info> app: BLE ADV EVT IDLE
12:05:55.299 -> 

12:06:08.609 -> <info> app: Connected to target 7E50F95DCE9F

12:06:08.609 -> <info> app: Peripheral connected

12:06:08.796 -> <info> app: ATT MTU exchange completed.

12:06:08.796 -> <info> app: Ble NUS max data length set to 0xF4(244)

12:17:17.625 -> <info> app: current instance index 1
12:17:17.625 ->

[siltvm]

Hung Bui ,Vidar Berg ,I modified the following parameters:

• Central Link Count:
  
  

  // <o> NRF_SDH_BLE_CENTRAL_LINK_COUNT - Maximum number of central links.
  #ifndef NRF_SDH_BLE_CENTRAL_LINK_COUNT
  #define NRF_SDH_BLE_CENTRAL_LINK_COUNT 10
  #endif
  

• Peripheral Link Count:
  
  

  // <o> NRF_SDH_BLE_PERIPHERAL_LINK_COUNT - Maximum number of peripheral links.
  #ifndef NRF_SDH_BLE_PERIPHERAL_LINK_COUNT
  #define NRF_SDH_BLE_PERIPHERAL_LINK_COUNT 1
  #endif
  

• Total Link Count:
  
  

  // <o> NRF_SDH_BLE_TOTAL_LINK_COUNT - Total link count.
  // <i> Maximum number of total concurrent connections using the default configuration.
  #ifndef NRF_SDH_BLE_TOTAL_LINK_COUNT
  #define NRF_SDH_BLE_TOTAL_LINK_COUNT 11
  #endif
  

• RAM Starting Address: 0x2000B198

After these changes, I observed the following behavior:

1. When Device 1 and Device 2 are connected, disconnecting Device 2 results in the following log output:

   11:03:06.626 -> <info> app: SCAN START
   11:03:06.626 -> <info> app: Device disconnected, conn_handle: 0x0, reason: 0x8
   11:03:06.626 -> <info> app: Erase bonds!
   11:03:06.626 -> <info> app: ENTER PM EVENT HANDLER: evt_id=12
   11:03:06.626 -> <info> peer_manager_handler: All peers deleted.
   11:03:06.626 -> <info> app: nrf_ble_scan_start : 0
   11:03:06.626 -> 
   11:03:06.626 -> <info> app: SCAN START
   11:03:06.626 -> <error> app: Fatal error
   11:03:06.626 -> <warning> app: System reset 
   

2. Following the system reset, the gateway attempts to connect to two nearby available peripherals.

I'm seeking assistance in understanding the root cause of this "Fatal error" and subsequent system reset . 

[Hung Bui]

Hi, 
If you want to see what cause the error, switch the project from Release to Debug. 

If you don't have that option you can try adding DEBUG to preprocessor symbols. 

Please try to test without bonding/security from what you provided it seems bonding was still used ? 
evt_id=5 = PM_EVT_CONN_SEC_CONFIG_REQ.