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 again, another question from us. Does any of these computers you have tested on have USB 3.0 ports or are you using USB 2.0 ports for all the cases, as that has shown different behavior in the past.

Would it be possible to take a sniffer trace of the communication between the faulty devices? It would be useful to check the packet sent over air up against what is reported by the error message you're seeing. 

Best regards,

Simon

[Vlad]

Hi Simon, just FYI: The be fair, the computer that I reported does not have have this issue, actually reports the same error once in a while - I'd say in 1 out 10 times, and not immediately but after 4-7 minutes of nRF Connect started receiving the packets.

[Wael]

Hi Simon,

The USB ports seem to be 3.0. please see the attached Device manager pic.

with regards to sniffer trace, I have never been able to get that to work properly because our device uses security code for communication. we really need to get this issue resolved. Is there a way we can setup a meeting with your development team so they can have access to our system and help them narrow down possible issue(s)? again, your help is greatly appreciated.

Regards,

Wael