h5_decode error, code: 0x802c, H5 error count

[Wael]

Hi,

I am getting this error message when using the nRF52 dev board but not when using the nRF51 dongle. I receive few packets and then it disconnects with this error message. here is the log from nRFConnect(version 3.6.1) desktop Bluetooth Low Energy application. I am connecting to an nRF52832 target device with an in house developed application that we have been using for years. 

it’s the nRFConnect that’s faulting because I can see the nRFConnect disconnect with the error message and the target device doesn’t disconnect until few seconds later with BLE_HCI_CONNECTION_TIMEOUT. I cant seem to find any information on this error that is helpful. any help is greatly appreciated. 

4857.2021-05-24T15_07_05.686Z-log.txt

and the log from terminal is this:

13> [00:00:00.000,000] <info> app: Event: FDS_EVT_INIT received (FDS_SUCCESS)
13> [00:00:00.000,000] <info> app: Read Record 0:
13> [00:00:00.000,000] <info> app: 00 FF FF FF FF FF FF FF|.
13> [00:00:00.000,000] <info> app: FF FF FF FF FF FF FF 00|.
13> [00:00:00.000,000] <info> app: 75 FF 00 00 |u..
13> [00:00:00.000,030] <info> app:
13>
13> [00:00:00.000,030] <info> app: Flash Record #1 NOT Found:
13> [00:00:00.000,061] <info> app: Event: FDS_EVT_INIT received (FDS_SUCCESS)
13>
13>
13>
13> [00:00:00.268,218] <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
13> [00:00:00.268,218] <error> nrf_ble_gatt: sd_ble_gap_data_length_update() (request) on connection 0x0 returned NRF_ERROR_RESOURCES.
13> [00:00:00.268,218] <error> nrf_ble_gatt: The requested TX/RX packet length is too long by 224/224 octets.
13> [00:00:00.268,249] <info> app: Unknown Acquisition Mode: 4
13> [00:00:00.268,249] <info> app: Acquisition Mode Updated to: 4
13> [00:00:00.268,249] <info> app: Connected
13> [00:00:00.280,364] <info> app: m_conn_handle = 0x0
13> [00:00:00.280,395] <info> app: PM Event: 5
13> [00:00:00.280,395] <info> app: PM Event: PM_EVT_CONN_SEC_PARAMS_REQ
13> [00:00:00.280,395] <info> app: Start encryption, pm_conn_secure returned 0
13> [00:00:00.286,285] <info> app: PM Event: 1
13> [00:00:00.286,285] <info> app: PM Event: 5
13> [00:00:00.286,285] <info> app: PM Event: PM_EVT_CONN_SEC_PARAMS_REQ
13> [00:00:00.286,315] <info> app: BLE_GAP_EVT_SEC_PARAMS_REQUEST
13> [00:00:00.286,315] <info> app: Passkey: 086574
13> [00:00:00.523,895] <info> app: BLE_GAP_EVT_CONN_SEC_UPDATE EVENT Received
13> [00:00:00.523,895] <info> app: PM Event: 2
13> [00:00:00.523,925] <info> app: Link secured. Role: 1. conn_handle: 0, Procedure: 2
13> [00:00:00.606,964] <info> app: PM Event: 14
13> [00:00:00.664,916] <info> app: max connection interval: 18
13>
13> [00:00:00.664,916] <info> app: min connection interval: 16
13>
13> [00:00:00.664,916] <info> app: err_code = 0x0 in update_conn_params
13> [00:00:00.664,947] <info> app: Acquisition Mode Updated to: 0
13> [00:00:00.665,527] <info> app: Transmit err_code = 0
13> [00:00:00.665,557] <info> app: hvn_tx_queue_count = 7, m_tx_queue_busy = 0
13> [00:00:00.665,557] <info> app: Transmit err_code = 0
13> [00:00:00.665,557] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.665,588] <info> app: Packet TX Complete Time = 713818, hvn_tx_queue_count = 7
13> [00:00:00.666,137] <info> app: Transmit err_code = 0
13> [00:00:00.666,137] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.666,168] <info> app: Transmit err_code = 0
13> [00:00:00.666,168] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.666,198] <info> app: Packet TX Complete Time = 636, hvn_tx_queue_count = 6
13> [00:00:00.666,198] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.666,748] <info> app: Transmit err_code = 0
13> [00:00:00.666,748] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.666,748] <info> app: Transmit err_code = 0
13> [00:00:00.666,778] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.666,839] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.666,839] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.667,358] <info> app: Transmit err_code = 0
13> [00:00:00.667,358] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.667,358] <info> app: Transmit err_code = 0
13> [00:00:00.667,358] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.667,480] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.667,510] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.667,968] <info> app: Transmit err_code = 0
13> [00:00:00.667,968] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.667,968] <info> app: Transmit err_code = 0
13> [00:00:00.667,968] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.668,121] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.668,151] <info> app: Packet TX Complete Time = 24, hvn_tx_queue_count = 7
13> [00:00:00.668,579] <info> app: Transmit err_code = 0
13> [00:00:00.668,579] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.668,579] <info> app: Transmit err_code = 0
13> [00:00:00.668,579] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.668,762] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.668,792] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.669,158] <info> app: Transmit err_code = 0
13> [00:00:00.669,189] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.669,189] <info> app: Transmit err_code = 0
13> [00:00:00.669,189] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.669,403] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.669,433] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.669,769] <info> app: Transmit err_code = 0
13> [00:00:00.669,769] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.669,799] <info> app: Transmit err_code = 0
13> [00:00:00.669,799] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.669,799] <info> app: Battery Count = 3323
13> [00:00:00.670,043] <info> app: Packet TX Complete Time = 678, hvn_tx_queue_count = 6
13> [00:00:00.670,074] <info> app: Packet TX Complete Time = 22, hvn_tx_queue_count = 7
13> [00:00:00.670,379] <info> app: Transmit err_code = 0
13> [00:00:00.670,379] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.670,410] <info> app: Transmit err_code = 0
13> [00:00:00.670,410] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.670,684] <info> app: Packet TX Complete Time = 674, hvn_tx_queue_count = 6
13> [00:00:00.670,989] <info> app: Transmit err_code = 0
13> [00:00:00.670,989] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.670,989] <info> app: Transmit err_code = 0
13> [00:00:00.671,020] <info> app: hvn_tx_queue_count = 4, m_tx_queue_busy = 0
13> [00:00:00.671,325] <info> app: Packet TX Complete Time = 693, hvn_tx_queue_count = 5
13> [00:00:00.671,600] <info> app: Transmit err_code = 0
13> [00:00:00.671,600] <info> app: hvn_tx_queue_count = 4, m_tx_queue_busy = 0
13> [00:00:00.671,600] <info> app: Transmit err_code = 0
13> [00:00:00.671,600] <info> app: hvn_tx_queue_count = 3, m_tx_queue_busy = 0
13> [00:00:00.671,997] <info> app: Packet TX Complete Time = 696, hvn_tx_queue_count = 4
13> [00:00:00.671,997] <info> app: Packet TX Complete Time = 22, hvn_tx_queue_count = 5
13> [00:00:00.672,027] <info> app: Packet TX Complete Time = 22, hvn_tx_queue_count = 6
13> [00:00:00.672,058] <info> app: Packet TX Complete Time = 24, hvn_tx_queue_count = 7
13> [00:00:00.672,210] <info> app: Transmit err_code = 0
13> [00:00:00.672,210] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.672,210] <info> app: Transmit err_code = 0
13> [00:00:00.672,210] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.672,637] <info> app: Packet TX Complete Time = 627, hvn_tx_queue_count = 6
13> [00:00:00.672,637] <info> app: Packet TX Complete Time = 24, hvn_tx_queue_count = 7
13> [00:00:00.672,821] <info> app: Transmit err_code = 0
13> [00:00:00.672,821] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.672,821] <info> app: Transmit err_code = 0
13> [00:00:00.672,821] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.673,278] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.673,278] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.673,400] <info> app: Transmit err_code = 0
13> [00:00:00.673,431] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.673,431] <info> app: Transmit err_code = 0
13> [00:00:00.673,431] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.673,919] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.673,950] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.673,950] <info> app: Max. conn. interval updated to 16
13> [00:00:00.673,950] <info> app: Min. conn. interval updated to 16
13> [00:00:00.674,011] <info> app: Transmit err_code = 0
13> [00:00:00.674,011] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.674,041] <info> app: Transmit err_code = 0
13> [00:00:00.674,041] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.674,560] <info> app: Packet TX Complete Time = 673, hvn_tx_queue_count = 6
13> [00:00:00.674,621] <info> app: Transmit err_code = 0
13> [00:00:00.674,621] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.674,621] <info> app: Transmit err_code = 0
13> [00:00:00.674,652] <info> app: hvn_tx_queue_count = 4, m_tx_queue_busy = 0
13> [00:00:00.675,170] <info> app: Packet TX Complete Time = 657, hvn_tx_queue_count = 5
13> [00:00:00.675,170] <info> app: Packet TX Complete Time = 21, hvn_tx_queue_count = 6
13> [00:00:00.675,201] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.675,231] <info> app: Transmit err_code = 0
13> [00:00:00.675,231] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.675,231] <info> app: Transmit err_code = 0
13> [00:00:00.675,231] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.675,781] <info> app: Packet TX Complete Time = 610, hvn_tx_queue_count = 6
13> [00:00:00.675,781] <info> app: Packet TX Complete Time = 23, hvn_tx_queue_count = 7
13> [00:00:00.675,842] <info> app: Transmit err_code = 0
13> [00:00:00.675,842] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.675,842] <info> app: Transmit err_code = 0
13> [00:00:00.675,842] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.676,391] <info> app: Packet TX Complete Time = 632, hvn_tx_queue_count = 6
13> [00:00:00.676,391] <info> app: Packet TX Complete Time = 24, hvn_tx_queue_count = 7
13> [00:00:00.676,452] <info> app: Transmit err_code = 0
13> [00:00:00.676,452] <info> app: hvn_tx_queue_count = 6, m_tx_queue_busy = 0
13> [00:00:00.676,452] <info> app: Transmit err_code = 0
13> [00:00:00.676,452] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.676,971] <info> app: Packet TX Complete Time = 632, hvn_tx_queue_count = 6
13> [00:00:00.677,032] <info> app: Transmit err_code = 0
13> [00:00:00.677,062] <info> app: hvn_tx_queue_count = 5, m_tx_queue_busy = 0
13> [00:00:00.677,062] <info> app: Transmit err_code = 0
13> [00:00:00.677,062] <info> app: hvn_tx_queue_count = 4, m_tx_queue_busy = 0
13> [00:00:00.677,642] <info> app: Transmit err_code = 0
13> [00:00:00.677,642] <info> app: hvn_tx_queue_count = 3, m_tx_queue_busy = 0
13> [00:00:00.677,673] <info> app: Transmit err_code = 0
13> [00:00:00.677,673] <info> app: hvn_tx_queue_count = 2, m_tx_queue_busy = 0
13> [00:00:00.678,253] <info> app: Transmit err_code = 0
13> [00:00:00.678,253] <info> app: hvn_tx_queue_count = 1, m_tx_queue_busy = 0
13> [00:00:00.678,283] <info> app: Transmit err_code = 0
13> [00:00:00.678,283] <info> app: hvn_tx_queue_count = 0, m_tx_queue_busy = 0
13> [00:00:00.678,863] <info> app: ........Waiting

any help would be greatly apprecaited.

Regards

[Simonr]

UPDATE: If you're on Mac or Linux J-Link MSD has to be disabled to avoid this, but as you didn't state what OS you were using I assumed you were using Windows.

I've discussed this with some of the nRFConnect devs today, and we have some ideas, but not yet a certain conclusion I'm afraid. h5 is the protocol used to transmit data between the connectivity and BLE-driver. An error here usually means there is packet loss or something wrong with the data to be transmitted.

Also, the NRF_ERROR_RESOURCES you're seeing from sd_ble_gap_data_length_update indicates that the SoftDevice being used has not been configured to support the data length for the given connection. What is the NRF_SDH_BLE_GAP_EVENT_LENGTH and NRF_SDH_BLE_GAP_DATA_LENGTH set to in your application?

Best regards,

Simon

[Wael]

Hi Simon,

thank you for staying on top of this issue for us. I am using a windows machine. and the 

#define NRF_SDH_BLE_GAP_EVENT_LENGTH 12

#define NRF_SDH_BLE_GAP_DATA_LENGTH 251

I did try to change the NRF_SDH_BLE_GAP_DATA_LENGTH to 23 and that did not help. I also want to repeat that my colleagues are NOT having this issue although they are running the same code/app and using the same nRF52 DK as the BLE dongle for the BLE App within nRFConnect. Furthermore, there PC is using the same BLE driver. please let me know if you have any other questions.

Regards,

Wael

[Simonr]

Okay, thank you for the update. Sorry about the late response! The specific h5-error you're seeing is described here by the way.

The fact that your colleague is not seeing this error with the same exact setup sounds very strange. Can you try changing the USB cable you're using to connect the nRF52DK to your computer? Are you able to test the nRF52 DK that your colleague is using or able to let him test the nRF52DK you're seeing the issue with so we can narrow down whether the issue is on your PC or with the DK? Can you try uninstalling nRFConnect, make sure that the following file is removed as well (a bug with nRFConnect v3.6.1 that shouldn't be related to this issue) C:\Users\***\AppData\Roaming\nrfconnect\settings.json. Then try reinstalling nRFConnect on the computer where this is failing.

A suggestion from our devs. It might be worth checking out the version of JLink dll you have on your and your colleague's computer as well. This should be stated in the start of the log file, but it seems you cut this from the log file provided in this case.

Best regards,

Simon

[Vlad]

I am Wael's colleague and I do not see the issue that Wael described on my laptop with BLE v.22.20.0.3 (11/27/2020) and nRFConnect 3.6.1. However I am seeing the issue on another laptop with BLE v.22.10.0.2 (10/28/2020) and the same version of nRFConnect and the same PCA10040 board.

[Simonr]

Thank you for the update Vladimir.

(v.22.20.0.3 (11/27/2020)) This is the J-Link version on your laptop, correct? Are you able to update it to v22.10.0.2 to see if that fixes the issue on this other laptop.

Simon