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]

Hi Wael

Time for another update. We're waiting for one of our experts to take a closer look packet length and decoding problems, they should be able to get back to us early next week.

Another possible culprit to the issue you're seeing has come to my attention. There are apparently some issues with J-Link UART communication where packets get garbled inbound from the JLink OB or SEGGER drivers that could ultimately cause an issue similar to what you're seeing. This should be fixed in J-Link version 7.50 and onwards. Could you try updating to J-Link v7.52d (most recent version) if you haven't already?

[Wael]

Hi Simonr,

I downloaded v7.52 and uninstalled the previous versions and unfortunately I'm still seeing the same issue. I hope this helps

Regards,

Wael

[Simonr]

Please note that a FW update is required on the device after the J-Link has been updated. Please make sure that you've done by calling an nrfjprog command that connects to the target device (nrfjprog -r) for example. 

Can you also provide what baud rate and other settings you're using? Is HW flow control used for instance?

Best regards,

Simon

UPDATE: Another thing that can be used to check if bytes are lost by the USB, is to collect data from the UART TX pin from nRF52 to SEGGER and compare packet content with what's reported.

[Wael]

hi Simon,

I did that and also made sure the nRF52 board got reprogrammed in nRFConnect by selecting different apps and then going back to Bluetooth Low Energy app. here are the port settings which I have never played with

Still the same issue.

Regards,

[Simonr]

Thanks! Did you try collecting data from the UART TX pin from nRF52 to SEGGER and compare packet content with the two? You could also try enabling flow control on your end to see if that makes any difference.

Best regards,

Simon

[Vlad]

Simonr said:

You could also try enabling flow control on your end to see if that makes any difference.

I tried and verified it does not make any difference.

[Vlad]

Simonr said:

Did you try collecting data from the UART TX pin from nRF52 to SEGGER and compare packet content with the two

Simon, I found it interesting that the error happens exactly on the 7th packet received, no matter what was the size/length of the previous packets. Please see below. Does it give you any clues?

[Vlad]

Simonr said:

Did you try collecting data from the UART TX pin from nRF52 to SEGGER and compare packet content with the two?

I did try, here is the result:

nRF Connect v3.7.1 BLE v2.5.3 Log:
14:13:54.565 Attribute value changed, handle: 0x16, value (0x): 12-00-19-C4-66-00-47-FF-FF-00-13-02-CD-FF-5F-40-F8-00-05-01
14:13:54.602 Attribute value changed, handle: 0x16, value (0x): 32-F4-00-46-00-00-00-0C-02-C1-FF-63-40-F2-00-07-74-00-47-01
14:13:54.642 Attribute value changed, handle: 0x16, value (0x): 52-FF-FF-00-13-02-DB-FF-62-40-F0-00-08-F4-00-00-86-F7-00-01
14:13:54.690 Attribute value changed, handle: 0x16, value (0x): 72-04-E4-01
14:13:54.718 Connection parameters updated for device C9:2B:A2:D3:7B:E2: interval 15ms, timeout 4000ms, latency: 0
14:13:55.162 h5_decode error, code: 0x802c, H5 error count: 1. raw packet: c0 c6 2e 02 0a 02 39 00 00 00 00 00 00 00 16 00 01 14 00 12 00 19 ca 08 00 48 00 05 00 0e c0
14:13:55.562 Reset performed on adapter COM5

...
The packet values of the next packet in the buffer at which the error happens:
12 00 19 CA 08 00 48 00 05 00 0E 02 C7 FF 64 40 FF 00 0A 02
...

[Vlad]

Vlad said:

14:13:54.690 Attribute value changed, handle: 0x16, value (0x): 72-04-E4-01

Note that the previously transmitted data is correct, including the last one received.