ble_app_uart example disconnects

[msmithRT]

Running through the ble uart example, connecting to the nRF connect app on my android phone. If I'm not actively sending data the bluetooth connection will time out on the nRF52 side within ~20s. None of the timeout values I've looked at seem to change the timeout period. The ble_blinkey examples, meanwhile, will stay connected indefinitely even without data.

I haven't noticed any differences in the ble setup or handlers that would account for the behaviour difference, and I'm not getting any error information on the RTT at logging level DEBUG.

 0> <info> app: Connected
 0> <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
 0> <info> app: Data len is set to 0xF4(244)
 0> <debug> app: ATT MTU exchange completed. central 0xF7 peripheral 0xF7
 0> <info> app: Disconnected

Checking the logs on nRF Connect (and bluetooth packet capture) shows that as far as the phone is concerned, it's a GATT CONN timeout.

[Bjørn Kvaale]

Weird. Looking at the ble_app_uart example, it seems it might be due to the BLE_GAP_EVT_DISCONNECTED event in the ble_evt_handler() in main.c. Have you timed it exactly? What phone are you using? This devzone case could be helpful.

[msmithRT]

 0> <info> app: Connected
 0> <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
 0> <info> app: Data len is set to 0xF4(244)
 0> <debug> app: ATT MTU exchange completed. central 0xF7 peripheral 0xF7
 0> <info> app: Unhandled event in ble_evt_handler
 0> <info> app: Event ID 0x3A
 0> <info> app: Disconnected
 0> <debug> app: Disconnect code 0x22

I dug into the disconnect codes, it looks like an 0x22, BLE_HCI_STATUS_CODE_LMP_RESPONSE_TIMEOUT.

0> [00:00:00.000,000] <info> app: Starting up.
 0> [00:00:00.000,000] <info> app: Starting up.
 0> [00:00:00.363,983] <info> app: Debug logging for UART over RTT started.
 0> [00:00:10.835,601] <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
 0> [00:00:10.835,937] <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
 0> [00:00:10.836,242] <debug> app: conn params event
 0> [00:00:10.836,456] <info> app: Connected
 0> [00:00:11.098,144] <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
 0> [00:00:11.098,541] <info> app: Data len is set to 0xF4(244)
 0> [00:00:11.098,754] <debug> app: ATT MTU exchange completed. central 0xF7 peripheral 0xF7
 0> [00:00:11.099,060] <info> app: Unhandled event in ble_evt_handler
 0> [00:00:11.099,273] <info> app: Event ID 0x3A
 0> [00:00:50.831,115] <info> app: Disconnected
 0> [00:00:50.831,298] <debug> app: Disconnect code 0x22

And then I got the timestamps working, so it looks like it's about 40s until the timeout.

However, after writing to the UART service it doesn't reset to 40s.

 0> [00:03:40.809,814] <debug> app: Received data from BLE NUS. Writing data on UART.
 0> [00:03:40.810,119] <debug> app:  61 61 61               |aaa     
 0> [00:03:40.810,424] <info> app: Unhandled event in ble_evt_handler
 0> [00:03:40.810,638] <info> app: Event ID 0x50
 0> [00:04:08.598,541] <info> app: Disconnected

I'm using an LGV20, Android 7.0.

[msmithRT]

I've obtained another android device running Android 6.0.1 which remains connected indefinitely.

 0> [00:01:01.844,421] <info> app: Event ID 0x24
 0> [00:01:01.937,347] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:01:01.937,591] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:01.937,805] <info> app: Event ID 0x12
 0> [00:01:02.207,122] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:01:02.207,366] <debug> app: conn params event
 0> [00:01:02.207,550] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:02.207,763] <info> app: Event ID 0x12
 0> [00:01:07.250,976] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:01:07.251,190] <debug> app: conn params event
 0> [00:01:07.251,403] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:07.251,617] <info> app: Event ID 0x12
 0> [00:02:45.183,868] <debug> nrf_sdh_ble: BLE event: 0x50.
 0> [00:02:45.184,173] <debug> app: Received data from BLE NUS. Writing data on UART.
 0> [00:02:45.184,417] <debug> app:  41 41 41 41 41 41 41 41|AAAAAAAA
 0> [00:02:45.184,417] <debug> app:  41 0A                  |A.      
 0> [00:02:45.185,028] <info> app: Unhandled event in ble_evt_handler
 0> [00:02:45.185,241] <info> app: Event ID 0x50

One thing I note is that with this device we don't get any nrf_ble_gatt ATT MTU exchange calls, which is where I assume our error is coming out of.

[Bjørn Kvaale]

Which SDK version are you using? If you are using sdk 15, you can try to comment out the nrf_ble_gatt_att_mtu_periph_set() function call in gatt_init(). If that does not work, I can recommend keeping the ATT MTU value at the default value of 23. There have been some issues with ATT MTU updates on Android 7, as you have noticed.

 

[msmithRT]

Sorry, I forgot to mention the SDK version. It's SDK15.

With the nrf_ble_gatt_att_mtu_periph_set call removed we get lots of BLE_GAP_EVT_CONN_PARAM_UPDATEs, then end up disconnecting anyway.

 0> [00:00:53.605,651] <info> app: Connected
 0> [00:00:53.818,756] <debug> nrf_sdh_ble: BLE event: 0x3A.
 0> [00:00:53.818,786] <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
 0> [00:00:53.818,817] <info> app: Data len is set to 0xF4(244)
 0> [00:00:53.818,817] <debug> app: ATT MTU exchange completed. central 0xF7 peripheral 0xF7
 0> [00:00:53.818,847] <info> app: Unhandled event in ble_evt_handler
 0> [00:00:53.818,878] <info> app: Event ID 0x3A
 0> [00:00:54.257,934] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:00:54.257,995] <info> app: Unhandled event in ble_evt_handler
 0> [00:00:54.257,995] <info> app: Event ID 0x12
 0> [00:00:54.558,959] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:00:54.558,990] <debug> app: conn params event
 0> [00:00:54.559,020] <info> app: Unhandled event in ble_evt_handler
 0> [00:00:54.559,051] <info> app: Event ID 0x12
 0> [00:00:59.577,880] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:00:59.577,911] <debug> app: conn params event
 0> [00:00:59.577,941] <info> app: Unhandled event in ble_evt_handler
 0> [00:00:59.577,941] <info> app: Event ID 0x12
 0> [00:01:28.333,862] <debug> nrf_sdh_ble: BLE event: 0x11.
 0> [00:01:28.334,106] <info> app: Disconnected
 0> [00:01:28.334,106] <debug> app: Disconnect code 0x22

I set NRF_SDH_BLE_GATT_MAX_MTU_SIZE to 23, and that definitely changes things. No disconnects for several minutes on Android 7.0 or 6.0.2, so I think it's fixed the immediate issue.

0> [00:01:43.788,177] <debug> nrf_sdh_ble: BLE event: 0x10.
 0> [00:01:43.788,269] <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
 0> [00:01:43.788,299] <error> nrf_ble_gatt: sd_ble_gap_data_length_update() (request) on connection 0x0 returned NRF_ERROR_RESOURCES.
 0> [00:01:43.788,299] <error> nrf_ble_gatt: The requested TX/RX packet length is too long by 224/224 octets.
 0> [00:01:43.788,330] <debug> app: conn params event
 0> [00:01:43.788,360] <info> app: Connected
 0> [00:01:44.171,325] <debug> nrf_sdh_ble: BLE event: 0x23.
 0> [00:01:44.171,356] <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 27 bytes.
 0> [00:01:44.171,356] <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
 0> [00:01:44.171,417] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:44.171,417] <info> app: Event ID 0x23
 0> [00:01:44.220,092] <debug> nrf_sdh_ble: BLE event: 0x24.
 0> [00:01:44.220,123] <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x0.
 0> [00:01:44.220,123] <debug> nrf_ble_gatt: max_rx_octets: 27
 0> [00:01:44.220,153] <debug> nrf_ble_gatt: max_tx_octets: 27
 0> [00:01:44.220,153] <debug> nrf_ble_gatt: max_rx_time: 328
 0> [00:01:44.220,184] <debug> nrf_ble_gatt: max_tx_time: 2120
 0> [00:01:44.220,184] <debug> app: ATT MTU exchange completed. central 0x17 peripheral 0x17
 0> [00:01:44.220,214] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:44.220,245] <info> app: Event ID 0x24
 0> [00:01:44.561,340] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:01:44.561,370] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:44.561,401] <info> app: Event ID 0x12
 0> [00:01:44.894,989] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:01:44.895,019] <debug> app: conn params event
 0> [00:01:44.895,050] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:44.895,050] <info> app: Event ID 0x12
 0> [00:01:49.888,885] <debug> nrf_sdh_ble: BLE event: 0x12.
 0> [00:01:49.888,916] <debug> app: conn params event
 0> [00:01:49.888,946] <info> app: Unhandled event in ble_evt_handler
 0> [00:01:49.888,946] <info> app: Event ID 0x12

If I'm reading the debug log correctly, the nRF52 is still attempting to increase the connection size to the UART buffer size, but it's getting refused and falling back to the MAX_MTU size.