DLE support from Android BLE 4.2 working but DLE Support from Windows BLE5.0 negotiation fails.

[Mark P. Mendelsohn]

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.

[bjorn-spockeli]

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

[bjorn-spockeli]

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.

[Mark P. Mendelsohn]

Fullscreen largemtu hp pavilion.log Download

 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

hp pavilion ble 5 02-20-20.pcapng

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;

[bjorn-spockeli]

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?

[Mark P. Mendelsohn]

default mtu size.pcapng

Fullscreen default mtu size.log Download

 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.

[bjorn-spockeli]

OK, that is interesting. I see that the MTU exchange procedure now occurs after all the LL transactions and is triggered by the master , instead of immediatly after the connection establishment triggered by the slave as before. So it could be that the time and place of the MTU exchange has a role to play here. 

Did you try leaving the MTU size at 247 on the Nordic side and then just delay the sd_ble_gattc_exchange_mtu_request() call that triggers the BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST from the slave? In my previous reply I stated that a delay should be added before the on_exchange_mtu_request_evt() call in nrf_ble_gatt_on_ble_evt(). THis is incorrect, it should have been the on_connected_evt() call under the BLE_GAP_EVT_CONNECTED case in nrf_ble_gatt_on_ble_evt() in nrf_ble_gatt.c

[Mark P. Mendelsohn]

Added a 500ms delay in on_connected_evt() just before the call to sd_ble_gattc_exchange_mtu_request(). It still did not work. I will be able to take an OTA trace in the morning and attach it.

[bjorn-spockeli]

Great. I'll wait for the OTA trace and then analyze it with the SoftDevice team to figure out what the cause of the issue is. 

[Mark P. Mendelsohn]

0743.hp pavilion large mtu 02-25-20.pcapng

Fullscreen 8322.large mtu hp pavilion 2-25-20 v2.log Download

 0> REBOOT (9)
 0> Bluetooth Name  NM04-000008 
 0> Board Type      D045 
 0> Model Type      ETM 
 0> FPGA Ver        Model 4 Version 4 
 0> Firmware Ver    1.8.330 
 0> Firmware Type   FIELD_BLE_UART
 0> SoftDevice Ver  6.1.0
 0> BootLoader Ver  6 (INSTALLED)
 0> Mfg Data Ver    4 
 0> Sys Config Ver  10 
 0> API Versions    OK
 0> Bluetooth       Enabled 
 0> UART            Enabled
 0> Stimulation     Enabled
 0> Acceleration    Disabled (0)
 0> Force Error     Disabled (0)
 0> Electrode Map   Field 8 Contact
 0> Reboot Reason   Watchdog Timeout (Bootloader)
 0> 
 0> wdt_register_long_timer:  2 for 191177
 0> BLE: Local BDADDR xEFF00F3689C3
 0> wdt_register_long_timer:  0 for 242305
 0> 0:00:01.439  PWR: Entering normal power
 0> WDT: enable 0
 0> Register TTAP: added handler[0]=x2C59D
 0> WDT: enable 0
 0> 0:00:01.442  STIM STATE: SEARCHING
 0> 0:00:01.443  ADV: Sys=FFFFFFFF Dev=0 VBat=4140 Amp=0 Err=00 Col=02 Prg=F Ins=0 Post=0 Stim=1 LowP=0 LowB=0 Sess=0 Buzz=1
 0> WDT: enable 1
 0> 0:00:01.556  STIM EVENT: DEVICE FOUND 
 0> 0:00:01.556  STIM STATE: VERIFYING
 0> SD:  26 BLE_GAP_EVT_ADV_SET_TERMINATED
 0> 0:00:02.092  Detected Device ID=x00000325 (not registered)
 0> 0:00:02.093  Registered trim data not found.
 0> 0:00:02.094  Connected to device x00000325
 0> 0:00:02.095  STIM EVENT: IPG CONNECTED 
 0> 0:00:02.095  STIM STATE: CONNECTED IDLE
 0> Unregister TTAP: handler not found: x45435
 0> 0:00:02.140  ADV: Sys=FFFFFFFF Dev=0 VBat=4097 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> BootLoader Ver  6 (INSTALLED)
 0> Mfg Data Ver    4 
 0> Sys Config Ver  10 
 0> API Versions    OK
 0> Bluetooth       Enabled 
 0> UART            Enabled
 0> Stimulation     Enabled
 0> Acceleration    Disabled (0)
 0> Force Error     Disabled (0)
 0> Electrode Map   Field 8 Contact
 0> Reboot Reason   Watchdog Timeout (Bootloader)
 0> 
 0> wdt_register_long_timer:  2 for 191177
 0> BLE: Local BDADDR xEFF00F3689C3
 0> wdt_register_long_timer:  0 for 242305
 0> 0:00:01.432  PWR: Entering normal power
 0> WDT: enable 0
 0> Register TTAP: added handler[0]=x2C59D
 0> WDT: enable 0
 0> 0:00:01.435  STIM STATE: SEARCHING
 0> 0:00:01.436  ADV: Sys=FFFFFFFF Dev=0 VBat=4145 Amp=0 Err=00 Col=02 Prg=F Ins=0 Post=0 Stim=1 LowP=0 LowB=0 Sess=0 Buzz=1
 0> WDT: enable 1
 0> 0:00:01.549  STIM EVENT: DEVICE FOUND 
 0> 0:00:01.549  STIM STATE: VERIFYING
 0> SD:  26 BLE_GAP_EVT_ADV_SET_TERMINATED
 0> 0:00:02.085  Detected Device ID=x00000325 (not registered)
 0> 0:00:02.086  Registered trim data not found.
 0> 0:00:02.087  Connected to device x00000325
 0> 0:00:02.088  STIM EVENT: IPG CONNECTED 
 0> 0:00:02.088  STIM STATE: CONNECTED IDLE
 0> Unregister TTAP: handler not found: x45435
 0> 0:00:02.133  ADV: Sys=FFFFFFFF Dev=0 VBat=4099 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:02:02.362  ADV: Sys=FFFFFFFF Dev=0 VBat=4062 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.426  ADV: Sys=FFFFFFFF Dev=0 VBat=4033 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:04:02.391  ADV: Sys=FFFFFFFF Dev=0 VBat=4005 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> NCE: bd_addr1 xEFF00F3689C3
 0> NCE: bd_addr2 x087190696FE9
 0> BLE: GAP connected.  Unauthenticated timer restarted
 0> SD:  23 BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST
 0> 0:07:00.134  ADV: Sys=FFFFFFFF Dev=0 VBat=4005 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:07:29.636  BLE: Inactivity timeout.  Connection Lockout timer started
 0> SD:  3B 
 0> BLE_GATTC_EVT_TIMEOUT
 0> WDT Event       0x0000000000000000
 0> WDT Channel 0   0x0000000800070889
 0> WDT Channel 1   0x0000000800070854
 0> WDT Channel 2   0x0000000800070553
 0> WDT Thread      3
 0> 
 0> wdt_register_long_timer:  1 for 200165
 0> 
 0> REBOOT (9)
 0> Bluetooth Name  NM04-000008 
 0> Board Type      D045 
 0> Model Type      ETM 
 0> FPGA Ver        Model 4 Version 4 
 0> Firmware Ver    1.8.330 
 0> Firmware Type   FIELD_BLE_UART
 0> SoftDevice Ver  6.1.0
 0> BootLoader Ver  6 (INSTALLED)
 0> Mfg Data Ver    4 
 0> Sys Config Ver  10 
 0> API Versions    OK
 0> Bluetooth       Enabled 
 0> UART            Enabled
 0> Stimulation     Enabled
 0> Acceleration    Disabled (0)
 0> Force Error     Disabled (0)
 0> Electrode Map   Field 8 Contact
 0> Reboot Reason   Watchdog Timeout (Bootloader)

[bjorn-spockeli]

Hi Mark, 

thanks for the trace. I forgot to ask which S132 version are you using? Looking at the trace its pretty clear that the nRF is not replying to the LL_LENGTH_REQ. 

Can you confirm that sd_ble_gap_data_length_update() returns NRF_SUCCESS when its called on the BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST event? I assume that you do not get the BLE_GAP_EVT_DATA_LENGTH_UPDATE event after calling sd_ble_gap_data_length_update()?

I also noticed that things break when its the nRF that sends the MTU Exchange Request, but when the Intel device( Central) initiates the MTU Exchange, then things proceed as normal. 

Comparing 0743.hp pavilion large mtu 02-25-20.pcapng with default mtu size.pcapng, I cant really see why the nRF does not respond to the LL_LENGTH_REQ in the   0743.hp pavilion large mtu 02-25-20.pcapng when it does this in the default mtu size.pcapn. The LL PDU order is exactly the same in both traces. 

Is this behavior 100% consistent, i.e. if you leave set the ATT MTU size higher than the default value then the negotiation Data length or ATT MTU negotioation halts every time?

Could you try to add an even longer delay in on_connected_evt() just before the call to sd_ble_gattc_exchange_mtu_request()? Like a full second or more? We want to see if the nRF replies to the LL_LENGTH_REQ then and if the Intel device then initiates the MTU Exchange procedure.