android large mtu.pcapnghp pavilion ble 5.pcapng
After the MTU size exchange of 247 bytes with Android LL_LENGTH_REQ/LL_LENGTH_RSP are exchanged with 123 byte octets for TX and RX. Data flows properly after that.
But with Windows, after the MTU size exchange of 247 bytes an LL_LENGTH_REQ is sent with 251 byte octet. No LL_LENGTH_RSP is sent by Nordic from the nRF52832
and no further data exchange takes place.
HI Mark,
the slave is sending a ATT_EXCHANGE_MTU_REQ in the same connection event as the master sends the LL_FEATURE_REQ. Our nrf_ble_gatt.c module will initiate a ATT MTU exchange, i.e. call sd_ble_gattc_exchange_mtu_request() if the NRF_SDH_BLE_GATT_MAX_MTU_SIZE is larger than the BLE_GATT_ATT_MTU_DEFAULT.
So it would seem that the nRF is waiting for the ATT_EXCHANGE_MTU_RSP, while the central is waiting for the LL_LENGTH_RSP. I am not quite sure which request that should have priority, need to check the spec / confer with the SoftDevice team.
Meanwhile, could you try to set NRF_SDH_BLE_GATT_MAX_MTU_SIZE == BLE_GATT_ATT_MTU_DEFAULT and see if that resolves the "deadlock"?
Best regards
Bjørn
Do you get the BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST event on the nRF side? Could you check whether the NRF device is calling sd_ble_gap_data_length_update() to respond to the LL_LENGTH_REQ as shown in the Data Length Update Procedure Message sequence chart.
0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED 0> 0:00:02.103 Detected Device ID=x00000325 (not registered) 0> 0:00:02.104 Registered trim data not found. 0> 0:00:02.106 Connected to device x00000325 0> 0:00:02.106 STIM EVENT: IPG CONNECTED 0> 0:00:02.106 STIM STATE: CONNECTED IDLE 0> Unregister TTAP: handler not found: x45239 0> 0:00:02.151 ADV: Sys=FFFFFFFF Dev=0 VBat=4130 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED 0> 0:03:02.444 ADV: Sys=FFFFFFFF Dev=0 VBat=4092 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED 0> SD: 10 BLE_GAP_EVT_CONNECTED 0> BLE: Remote x087190696FE9 0> BLE: GAP connected. Unauthenticated timer restarted 0> 0:05:25.881 ADV: Sys=FFFFFFFF Dev=0 VBat=4092 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: 23 BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST 0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED 0> SD: 11 BLE_GAP_EVT_DISCONNECTED 0> 0:05:54.947 BLE: Disconnect Reason x0013 (TERM BY HOST) 0> PMM: DISCONNECTED, active 0xFFFF keep_bond_state 0 0> 0:05:54.967 ADV: Sys=FFFFFFFF Dev=0 VBat=4092 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED
Attached is a new set of traces from both OTA and RTT sides.
We are getting the BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST. There was no
initial reply with sd_ble_gap_data_length_update, but it is now added. It did not affect the outcome,
however.
1745 case BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST:
1746 {
1747 ble_gap_data_length_params_t dl_params =
1748 {
1749 .max_tx_octets = BLE_GAP_DATA_LENGTH_AUTO,
1750 .max_rx_octets = BLE_GAP_DATA_LENGTH_AUTO,
1751 };
1752
1753 ret_code_t err_code = sd_ble_gap_data_length_update(p_evt->conn_handle, &dl_params, NULL);
1754
1755 APP_ERROR_CHECK(err_code);
1756 } break;
According to the RTT logs from the nRF the connection is disconnected with reason 0x13( BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION), i.e. the central tore down the connection. This is not shown in the on-air trace, as both slave and master keeps sending empty PDU after the LL_LENGTH_REQ. Did you stop the capture before the disconnection occured?
I assume that sd_ble_gap_data_length_update() returns NRF_SUCESS? The actual LL_LENGTH_RSP is sent asynch from the sd_ble_gap_data_length_update() call and you will get the BLE_GAP_EVT_DATA_LENGTH_UPDATE event when the response has been sent. Do you recieve this event? If the link is disconnected before this occurs, then that explains the missing BLE_GAP_EVT_DATA_LENGTH_UPDATE event and the missing LL_LENGTH_RSP, but the fact that the on-air trace indicates that the link is still active puzzles me.
Just to check if the ATT_EXCHANGE_MTU_REQ is casing the issues, could you try to add short delay before the on_exchange_mtu_request_evt call under the BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST case in nrf_ble_gatt_on_ble_evt() in nrf_ble_gatt.c?
0> BLE: Local BDADDR xEFF00F3689C3 0> 0:00:01.409 PWR: Entering normal power 0> 0:00:01.411 STIM STATE: SEARCHING 0> 0:00:01.413 ADV: Sys=FFFFFFFF Dev=0 VBat=4160 Amp=0 Err=00 Col=02 Prg=F Ins=0 Post=0 Stim=1 LowP=0 LowB=0 Sess=0 Buzz=1 0> 0:00:01.526 STIM EVENT: DEVICE FOUND 0> 0:00:01.526 STIM STATE: VERIFYING 0> 0:00:02.062 Detected Device ID=x00000325 (not registered) 0> 0:00:02.062 Registered trim data not found. 0> 0:00:02.064 Connected to device x00000325 0> 0:00:02.064 STIM EVENT: IPG CONNECTED 0> 0:00:02.065 STIM STATE: CONNECTED IDLE 0> 0:00:02.110 ADV: Sys=FFFFFFFF Dev=0 VBat=4160 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> 0:01:01.477 ADV: Sys=FFFFFFFF Dev=0 VBat=4130 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: BLE_GAP_EVT_TIMEOUT 0> SD: BLE_GAP_EVT_CONNECTED 0> BLE: Remote x087190696FE9 0> NCE: bd_addr1 xEFF00F3689C3 0> NCE: bd_addr2 x087190696FE9 0> BLE: GAP connected. Unauthenticated timer restarted 0> 0:03:46.530 ADV: Sys=FFFFFFFF Dev=0 VBat=4130 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST 0> SD: BLE_GAP_EVT_DATA_LENGTH_UPDATE 0> SD: BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST 0> SD: BLE_GAP_EVT_SEC_PARAMS_REQUEST 0> PM: PM_EVT_CONN_SEC_START 0> SD: BLE_GAP_EVT_CONN_SEC_UPDATE 0> SD: BLE_GAP_EVT_AUTH_STATUS 0> PM: PM_EVT_CONN_SEC_SUCCEEDED 0> PM: Connection secured. Procedure: 1 Role: 1 conn_handle: 0 0> PMM: CONNECTED, stored 1 peers 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> SD: BLE_GATTS_EVT_WRITE 0> NUS:BLE_GATTS_EVT_WRITE 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> SD: BLE_GATTS_EVT_WRITE 0> NUS:BLE_GATTS_EVT_WRITE 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> SD: BLE_GATTS_EVT_WRITE 0> NUS:BLE_GATTS_EVT_WRITE 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> SD: BLE_GAP_EVT_CONN_PARAM_UPDATE 0> SD: BLE_GATTS_EVT_SYS_ATTR_MISSING 0> PM: PM_EVT_LOCAL_DB_CACHE_APPLIED 0> SD: BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST 0> NUS:BLE_GATTS_EVT_AUTHORIZE_REQUEST 0> NCE: bd_addr1 x087190696FE9 0> NCE: bd_addr2 xEFF00F3689C3 0> 0:03:53.660 PK: Authentication OK 0> BLE: Passkey received. Unauthorized timer restarted 0> SD: BLE_GAP_EVT_CONN_PARAM_UPDATE 0> SD: BLE_GATTS_EVT_WRITE 0> NUS:BLE_GATTS_EVT_WRITE 0> 0:03:53.929 BLE host detected 0> 0> 0> 0:03:53.931 Session Start 0> Session Type=Engineering 0> 0:03:53.931 ACK: 000000 0> 0> BLE: Connection in session. Session timer restarted 0> PMM: ENTER_UNPROTECTED, active id=x0000 0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED 0> SD: BLE_GATTS_EVT_HVN_TX_COMPLETE 0> SD: BLE_GAP_EVT_CONN_PARAM_UPDATE 0> 0:04:01.471 ADV: Sys=FFFFFFFF Dev=0 VBat=4087 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: BLE_GATTS_EVT_HVN_TX_COMPLETE 0> SD: BLE_GATTS_EVT_HVN_TX_COMPLETE 0> SD: BLE_GAP_EVT_DISCONNECTED 0> 0:04:09.184 BLE: Disconnect Reason x0013 (TERM BY HOST) 0> PMM: DISCONNECTED, active 0x0 0> 0:04:09.185 BLE host terminated 0> 0:04:09.186 STIM EVENT: SESSION END 0> PMM: EXIT_UNPROTECTED, active=0xFFFF 0> 0:04:09.241 ADV: Sys=FFFFFFFF Dev=0 VBat=4087 Amp=0 Err=00 Col=02 Prg=F Ins=3 Post=0 Stim=2 LowP=0 LowB=0 Sess=0 Buzz=1 0> SD: BLE_GAP_EVT_TIMEOUT
When the default MTU size is used on the Nordic side, the negotiations are successful.
