Queued write response fails

[nrbrook]

iOS is using queued writes to send data to my nRF52832 application. For some reason, on the third queued write reply (in nrf_ble_qwr.c) sd_ble_gatts_rw_authorize_reply returns NRF_ERROR_INVALID_STATE.

I modified nrf_ble_qwr.c to log every time it calls sd_ble_gatts_rw_authorize_reply anywhere. I am sure that my code is not calling it, as I also log everywhere I call it too. The log output looks like this:

<debug> nrf_sdh_ble: BLE event: 0x1.
<debug> nrf_sdh_ble: BLE event: 0x51.
<info> app: prepare reply
<debug> nrf_sdh_ble: BLE event: 0x51.
<info> app: prepare reply
<debug> nrf_sdh_ble: BLE event: 0x51.
<info> app: prepare reply
<error> KFPAL: ERROR 8 [NRF_ERROR_INVALID_STATE] at ...KFPAL_Nordic_bluetooth.c:446
PC at: 0x000268F1
<error> KFPAL: End of error report

this occurs in the sd_ble_gatts_rw_authorize_reply call in on_prepare_write in nrf_ble_qwr.c. Unless sd_ble_gatts_rw_authorize_reply is being called by another nrf library, it is only being called from nrf_ble_qwr.c. I'm really struggling to understand why INVALID_STATE is being returned.

[Hung Bui]

Hi Nick, 

What do you have at KFPAL_Nordic_bluetooth.c line 446 ? 

If you are not sure where sd_ble_gatts_rw_authorize_reply () being called, and if other module is using it you can do a "Find in Files" and find all location that function is called. 

Please add the log in each of the events inside nrf_ble_qwr_on_ble_evt() it would help to detect the last event before the assert. 

Have you tried to test with the \examples\ble_peripheral\experimental\ble_app_queued_writes example ?

Please also capture a sniffer trace, it help analyzing what happens over the air. 

[nrbrook]

Hi,

KFPAL_Nordic_bluetooth.c line 446 is the QWR error callback

static void queued_write_error_handler(uint32_t nrf_error)
{
    APP_ERROR_HANDLER(nrf_error);
}

I am now confident that I am logging everywhere sd_ble_gatts_rw_authorize_reply is called including in libraries.

I am logging BLE events from the softdevice as you can see in the logs (NRF_SDH_BLE_LOG_ENABLED=1), so these are the only BLE events occurring.

Here's a packet log captured from the iPad. You can see it never receives a response to the third write. I suspect this could actually be a softdevice bug. Queued writes with only two writes work fine.

I haven't tried your example but I think it is broken.

[Hung Bui]

Hi Nick, 

Thanks for the link. I think it's not related to the issue you are having here. You can add the fix to initialize the cur_evt.rcvd_data array before calling nrf_ble_qwr_value_get() inside nrf_ble_qwrs_on_qwr_evt(). memset(cur_evt.rcvd_data,0,NRF_BLE_QWRS_MAX_RCV_SIZE); should fix it. 

Have you tried to add logging inside nrf_ble_qwr_on_ble_evt() event ? We would need to find which function throw the error. 

I'm looking for a way to reproduce the issue here. Could you describe your iphone app ? I can see in the log it's doing 3 queued writes, each has 180 bytes. Is it possible to replace the iphone with a nRF52 as a central device ? So we can reproduce here ? It's the best if you can reproduce with ble_app_queued_writes, this example has both sides running on nRF52. 

[nrbrook]

No, the issue is not related to the example bug, I just meant I can't test the example as-is. That would also not fix it as no buffer is set to cur_evt.rcvd_data.

The event is prepare write request (BLE_GATTS_OP_PREP_WRITE_REQ) (I logged "prepare reply" on this event in nrf_ble_qwr.c on_prepare_write just before the call to sd_ble_gatts_rw_authorize_reply).

The App uses peripheral.maximumWriteValueLength(for: .withResponse) to get the max write length which is 512 in my testing. Then I write a 512 byte Data with peripheral.writeValue(remaining.subdata(in: 0..<lengthToWrite), for: c, type: .withResponse). iOS then uses queued writes to send that data. It should be fairly easy to reproduce, I'm using an iPad Pro 11" with iOS 13.3. I've already spent a lot of time on this issue though so I can't really investigate further right now. I'm just reducing sent data length in the app for now.

[Hung Bui]

Hi Nick, 

rcvd_data is defined as an array not a pointer: 

    uint8_t               rcvd_data[NRF_BLE_QWRS_MAX_RCV_SIZE];

So the array has the buffer, it's just not initialized to 0 and I'm not sure initialized to 0 is really needed anyway. 
Please try to test with ble_app_queued_writes so we have an aligned test base. 
I will try to test here with what you described. 

[Hung Bui]

Hi Nick, 

I think I might find the root cause. In our queued write example we set the MEM_BUFF_SIZE to 512. This is the user memory provided to the softdevice to receive the queued writes (I assume you also use stack handled queued write, not app handled).

It's not the same as the rcvd_data[NRF_BLE_QWRS_MAX_RCV_SIZE]; which is handled by the qwrs module. 

If it's the case please try to test increase the User mem buffer to for example 1024.

In my test here if I leave the MEM_BUFF_SIZE =512  (thus m_buffer size array of 512 bytes) I got INVALID_STATE after 400+ bytes transmitted (there are lots of overhead in queued writes) it fixed after I increase the user mem. 

Please note that, queued write usually used when you want to update multiple characteristics at once. If you want to do a normal write, you can simply use normal write (with or without authorization). 

[nrbrook]

Ok thanks. So for receiving 512 bytes of data via queued write, what should MEM_BUFF_SIZE be? iOS uses queued writes for large data size, so I don't really have control over it. Thanks

[Hung Bui]

It depends on the overhead of queued writes you have. There are 5 bytes of overhead per Prepare Write Request:

So you need to know roughly the size of the data you going to receive. And the ATT MTU size to calculate the number of Prepare Write Request. 

Again, the queued write is designed so that you can write multiple characteristic at the same time. If you plan to write only one characteristic, or if you don't have the requirement of updating multiple of them at the same time, you can just use normal write.