pc-ble-driver reports “Failed to decode event, error code is 14/0xe”.

[Paul Bradford]

I'm using the nrf52840 with connectivity firmware and S140 SoftDevice, accessed through pc-ble-driver version 4.1.1, with NRF_SD_BLE_API=6

Occasionally pc-ble-driver fails to decode an advertisement event, and notifies my application with a status callback with PKT_DECODE_ERROR and message “Failed to decode event, error code is 14/0xe”.  Error code 14 is NRF_ERROR_NULL.  I have tracked down the cause of the NRF_ERROR_NULL.

I’ve debugged enough to find out what event is received over the virtual serial port – hex dumps of a sample invalid event are below.

In “ble_data_t_dec” this decodes to a ‘buf_id’ of zero, and it then calls “app_ble_gap_adv_buf_unregister” with zero, which returns a nullptr. That nullptr passed to ‘SER_PULL_len16data’ is invalid and causes it to return NRF_ERROR_NULL, which is the error reported to my application.  

So pc-ble-driver expects that the connectivity firmware will never give it an advertisement with this “buf_id” of zero. What is causing this?

Hex dump of invalid event (62 bytes):

1d 00 ff ff 03 00 04 68 ce e3 b1 14 7d fe 00 00

00 00 00 00 01 ff 7f e3 27 ff 00 00 00 00 00 00

18 00 01 02 01 1a 14 ff 4c 00 01 00 00 00 00 00

00 40 00 00 00 00 00 00 00 00 00 09 03 03

 

Numbering the bytes starting from zero, the “buffer id” is bytes 27-31 (decimal)

[Krzysztof Chruscinski]

buf_id = 0 would indicate that buffer was already freed on connectivity side. One case that comes to my mind is a race between ADV_SET_TERMINATED event and ADV_REPORT event. Do you have logs which would show traffic before that error?

[Paul Bradford]

Here's a fragment of my code that's preparing to call "sd_ble_gap_adv_set_configure", indicating that we should never get event BLE_GAP_EVT_ADV_SET_TERMINATED:

// Because we set both 'duration' and 'max_adv_evts' to zero, advertising won't auto-stop,
// so we'll never get event BLE_GAP_EVT_ADV_SET_TERMINATED according to devzone.nordicsemi.com/.../bug-ble_gap_evt_adv_set_terminated-is-never-raised
ble_gap_adv_params_t     m_adv_params;
m_adv_params.duration = BLE_GAP_ADV_TIMEOUT_GENERAL_UNLIMITED;
m_adv_params.max_adv_evts = 0;// 0 means no limit.

This code is setting up undirected advertising (BLE_GAP_ADV_TYPE_NONCONNECTABLE_NONSCANNABLE_UNDIRECTED). How is undirected advertising related to the events I receive because I'm scanning? Are undirected advertising and scanning tied together in some way I don't understand?

The event whose decoding leads to the 'Failed to decode event' error is BLE_GAP_EVT_ADV_REPORT.  That event has a zero 'buffer id'. What 'buffer id' is this, and what would cause it to be freed?

[Paul Bradford]

HI Krzysztof,

The test program I attached to my other support case reproduces this problem intermittently: devzone.nordicsemi.com/.../disconnecting-while-operations-are-in-progress-never-gives-ble_gap_evt_disconnected-event

Can you answer my questions from April 23. I'll restate my questions and add another

1. Your reply on April 23 said "that buffer was already freed". What buffer?

2. Is there some race condition with the SoftDevice receiving advertisements around the time sd_ble_gap_scan_stop is called, which could cause this?

3. The event whose decoding leads to the 'Failed to decode event' error is BLE_GAP_EVT_ADV_REPORT, which I receive because I'm scanning.  That event has a zero 'buffer id'. What 'buffer id' is this, and what would cause it to be freed?

4. Your April 23 reply talked about a race condition involving ADV_SET_TERMINATED, which is an event related to sending out advertisements, but which won't be received with my configuration. How is sending undirected advertisements related to the event BLE_GAP_EVT_ADV_REPORT I receive because I'm scanning? Are undirected advertising and scanning tied together in some way I don't understand?

-Paul

-Paul

[Krzysztof Chruscinski]

It is all about buffers coming from the application to the softdevice API. When scanning or advertising is started buffer content and buffers for incoming packets are provided to the softdevice API and softdevice event shall return same pointer in the event. Also if timeout occurs or scaning/advertising is terminated then buffer shall be returned to the application. In case of serialization application and softdevice are on different chips (application on PC in case of pc-ble-driver) so dedicated managing mechinism must be addded.

When the is a call to softdevice which provides the buffer then on application side (PC) pointer is stored in small database and ID is assigned. This ID is passed to connectivity. Connectivity allocated buffer from the pool and assigns the same ID. When buffer is sent back to the application then data comes together with that ID, buffer returned to the pool on connectivity side. On application side when event is received, database is checked for that ID to get pointer to the user buffer and data received from the connectivity is stored in that buffer.

So reported eror would suggest that something went wrong in that chain, e.g. buffer was already freed. Advertising and scanning uses same pool of data buffers.

Hope, I will be able to reproduce. No luck so far.

[Paul Bradford]

The place where the problem first manifests is in the firmware that creates the BLE_GAP_EVT_ADV_REPORT event with a buffer ID of 0, which is not a valid buffer ID. The buffer that should be used for the BLE_GAP_EVT_ADV_REPORT event is the third argument to sd_ble_gap_scan_start. That buffer remains valid until sd_ble_gap_scan_stop is called. I am trying to determine, using the test program, if I call sd_ble_gap_scan_stop immediately before seeing the 'Failed to decode' error.   If this happens right after I call sd_ble_gap_scan_stop, that would imply there is some race condition in the firmware when it is processing an incoming advertisement packet at the same time that sd_ble_gap_scan_stop is called.    If I do not call sd_ble_gap_scan_stop immediately before the error, what else could cause that buffer to be freed?

[Paul Bradford]

I have confirmed that when I get “Failed to decode event, error code is 14/0xe” i have not called sd_ble_gap_scan_stop any time recently.  

[Krzysztof Chruscinski]

is it possible that you are creating multiple advertising sets. I see that there are fixed 8 slots/shadow buffers used for scanning and advertising. In theory, it can be drained. I'm still not sure why i cannot reproduce it. Will try again next week.