About the problem of BLE disconnection caused by the pm_local_database_has_changed()

[Chang.tsai]

Hello, I have trouble developing BLE devices with Nordic NRF5280 and SDK 15.3.

I use pm_local_database_has_changed() on the product to notify the bound device of a BLE service update,

But this function seems to cause BLE disconnection.

At first I thought it was caused by some conflict in the program,

So I tried to use the example on the dev kit nRF52840 DK and test it again with nRF Connect on the phone and I get the same result.

I'm using SDK 15.3 example ble_app_gatts

This is the debug log I got from the development board nRF52840 DK.

Fullscreen pm_local_database_has_changed test log.txt Download

 0> <info> main: main(): 
 0> <info> main: main(): ------------------------------------------------------------------------
 0> <info> main: main(): GATT Service server started 
 0> <info> main: on_whitelist_req(): Starting scan.
 0> <warning> main: ble_evt_handler(): BLE Connect, conn_handle: 0x0.
 0> <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
 0> <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT
 0> <warning> main: ble_evt_handler(): GATT Server Timeout.
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_CONFIRMED
 0> <warning> main: ble_evt_handler(): BLE Disconnected. conn_handle: 0x0, reason: 0x16.
 0> 
 0> 
 0> <info> main: on_whitelist_req(): Starting scan.
 0> <warning> main: ble_evt_handler(): BLE Connect, conn_handle: 0x0.
 0> <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
 0> <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT 
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_CONFIRMED 
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT 
 0> <warning> main: ble_evt_handler(): GATT Server Timeout.
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_CONFIRMED 
 0> <warning> main: ble_evt_handler(): BLE Disconnected. conn_handle: 0x0, reason: 0x16.
 0> 
 0> 
 0> <info> main: on_whitelist_req(): Starting scan.
 0> <warning> main: ble_evt_handler(): BLE Connect, conn_handle: 0x0.
 0> <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
 0> <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT 
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_CONFIRMED 
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT 
 0> <warning> main: ble_evt_handler(): GATT Server Timeout.
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_CONFIRMED
 0> <warning> main: ble_evt_handler(): BLE Disconnected. conn_handle: 0x0, reason: 0x16.
 0> 

Every time I press Key2 at least 10 seconds,

It can be found that sometimes the PM_EVT_SERVICE_CHANGED_IND_CONFIRMED event is received after the Time out disconnection is triggered, and this time is about 30 seconds.

Please help me to solve the problem that pm_local_database_has_changed() will cause bluetooth disconnection.

[Sigurd]

Hi,

Could you upload a sniffer trace that shows the issue?

https://www.nordicsemi.com/Products/Development-tools/nrf-sniffer-for-bluetooth-le

[Chang.tsai]

Sorry for taking so long to get back to you, 

I've never used bluetooth sniffing for tracking signals before, so it took me a lot of time to learn how to use it.

This time I modified the examples\ble_peripheral\ble_app_hrs as a test program on the development board,

Because it is more similar to the function of our product on BLE.

I use the Android phone to open nRF Connect and use Bluetooth to connect to the development board,

Then subscribe to the characteristic value Service Changed(0x2A05) under Generic Attribute(0x1801).

Then press key_2 on the development board to trigger pm_local_database_has_changed().

This is the sniffer trace I recorded with wireshark.

2022-10-14_14_58_BLE_Service_Change_err.pcapng

And this is the RTT log I recorded from the development board.

Fullscreen 2022_10-14_14_58_RTT_Log.log Download

# SEGGER J-Link RTT Viewer V6.30i Terminal Log File
# Compiled: 18:15:39 on Mar 23 2018
# Logging started @ 14 Oct 2022 14:59:06
 0> <debug> nrf_ble_lesc: Initialized nrf_crypto.
 0> <debug> nrf_ble_lesc: Initialized nrf_ble_lesc.
 0> <debug> nrf_ble_lesc: Generating ECC key pair
 0> <info> main: main(): 
 0> <info> main: main(): ------------------------------------------------------------------------
 0> <info> main: Heart Rate Sensor example started.
 0> <info> main: main(): BLE isn't erase bonds(0).
 0> <warning> main: BLE MAC Addr:CC:E5:0B-82:AF:A2
 0> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
 0> <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
 0> <warning> main: ble_evt_handler(): BLE Connect, conn_handle: 0x0, count = 641633.
 0> <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
 0> <info> main: GATT ATT MTU on connection 0x0 changed to 247.
 0> <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
 0> <debug> nrf_ble_gatt: max_rx_octets: 27
 0> <debug> nrf_ble_gatt: max_tx_octets: 251
 0> <debug> nrf_ble_gatt: max_rx_time: 328
 0> <debug> nrf_ble_gatt: max_tx_time: 2120
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT.
 0> --------------------------------------------------
 0> Service change indcation, 1 sec count start.
 0> one_sec_count_timeout_handler(): 00, 01, 02, 03, 04, 05, 06, 07, 08, 09
 0> 10, 11, 12, 13, 14, 15, 16, 17, 18, 19
 0> 20, 21, 22, 23, 24, 25, 26, 27, 28<debug> main: GATT Server Timeout.
 0> , 29<info> main: Fast advertising.
 0> <info> main: Disconnected, reason 22.
 0> 
 0> 
 0> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
 0> <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
 0> <warning> main: ble_evt_handler(): BLE Connect, conn_handle: 0x0, count = 2154892.
 0> <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
 0> <debug> nrf_ble_gatt: max_rx_octets: 27
 0> <debug> nrf_ble_gatt: max_tx_octets: 251
 0> <debug> nrf_ble_gatt: max_rx_time: 328
 0> <debug> nrf_ble_gatt: max_tx_time: 2120
 0> <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
 0> <info> main: GATT ATT MTU on connection 0x0 changed to 247.
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT.
 0> --------------------------------------------------
 0> Service change indcation, 1 sec count start.
 0> one_sec_count_timeout_handler(): 00, 01, 02, 03, 04, 05, 06, 07, 08, 09
 0> 10, 11, 12, 13, 14, 15, 16, 17, 18, 19
 0> 20, 21, 22, 23, 24, 25, 26, 27, 28<debug> main: GATT Server Timeout.
 0> , 29
 0> 30<info> main: Fast advertising.
 0> <info> main: Disconnected, reason 22.
 0> 
 0> 
 0> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
 0> <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
 0> <warning> main: ble_evt_handler(): BLE Connect, conn_handle: 0x0, count = 3874487.
 0> <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
 0> <info> main: GATT ATT MTU on connection 0x0 changed to 247.
 0> <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
 0> <debug> nrf_ble_gatt: max_rx_octets: 27
 0> <debug> nrf_ble_gatt: max_tx_octets: 251
 0> <debug> nrf_ble_gatt: max_rx_time: 328
 0> <debug> nrf_ble_gatt: max_tx_time: 2120
 0> <warning> main: bsp_event_handler(): BSP_EVENT_KEY_2
 0> <warning> main: pm_evt_handler(): PM_EVT_SERVICE_CHANGED_IND_SENT.
 0> --------------------------------------------------
 0> Service change indcation, 1 sec count start.
 0> one_sec_count_timeout_handler(): 00, 01, 02, 03, 04, 05, 06, 07, 08, 09
 0> 10, 11, 12, 13, 14, 15, 16, 17, 18, 19
 0> 20, 21, 22, 23, 24, 25, 26, 27, 28<debug> main: GATT Server Timeout.
 0> , 29<info> main: Fast advertising.
 0> <info> main: Disconnected, reason 22.
 0> 
 0> 

# Logging stopped @ 14 Oct 2022 15:02:37

[Sigurd]

Hi,

Looks like the phone just ignores the service changed indication. I can't see any confirmation sent from the phone.

You then get the GATT Server Timeout event, and you disconnect because of that.

        case BLE_GATTS_EVT_TIMEOUT:
            // Disconnect on GATT Server timeout event.
            NRF_LOG_DEBUG("GATT Server Timeout.");
            err_code = sd_ble_gap_disconnect(p_ble_evt->evt.gatts_evt.conn_handle,
                                             BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION);
            APP_ERROR_CHECK(err_code);
            break;

What phone model/brand are you using? Are you seeing this issue with other phones?