Windows notifications stopped with high MTU in pc-ble-driver-py

[Florian Zierer]

Hi there,

I am trying to transmit data with high MTUs via pc-ble-driver-py. The data is sent from an nrf52840 with own firmware.

After the bug in nrfutil was fixed, https://devzone.nordicsemi.com/f/nordic-q-a/55269/nrfutil-dfu-upload-extremely-slow I implemented my own script based on this.

I am transmitting data every 10ms from the firmware via NUS (notifications) to the PC.

On linux I can transfer data without problems with MTU set to 247. On windows after some time, the data is just not received any longer. It seems the data is not sent any longer from the firmware (I get NRF_ERROR_RESOURCES from ble_nus_data_send/sd_ble_gatts_hvx) and can't see any errors on the PC side (with debugging set high).

DEBUG:pc_ble_driver_py.observers:evt> on_gattc_evt_hvx status(BLEGattStatusCode.success) conn(0)
 error_handle(0)
 attr_handle(18)
 hvx_type(BLEGattHVXType.notification)
 data([0, 93, 98, 91, 10, 2, 24, 8, 16, 180, 131, 1, 42, 12, 0, 0, 28, 189, 0, 0, 198, 60, 0, 96, 123, 63, 50, 12, 236, 81, 152, 63, 133, 235, 113, 63, 205, 204, 156, 191, 61, 0, 240, 151, 65, 90, 48, 229, 211, 3, 228, 208, 3, 174, 209, 3, 246, 201, 3, 163, 227, 3, 191, 222, 3, 236, 231, 3, 246, 208, 3, 229, 223, 3, 182, 242, 3, 186, 211, 3, 141, 229, 3, 187, 219, 3, 161, 222, 3, 142, 246, 3, 205, 208, 3])
DEBUG:pc_ble_driver_py.observers:evt> on_gattc_evt_hvx status(BLEGattStatusCode.success) conn(0)
 error_handle(0)
 attr_handle(18)
 hvx_type(BLEGattHVXType.notification)
 data([0, 93, 98, 91, 10, 2, 24, 8, 16, 200, 131, 1, 42, 12, 0, 0, 23, 189, 0, 0, 172, 60, 0, 192, 122, 63, 50, 12, 205, 204, 156, 63, 102, 102, 134, 63, 174, 71, 161, 191, 61, 0, 216, 153, 65, 90, 48, 226, 211, 3, 219, 208, 3, 162, 209, 3, 214, 201, 3, 216, 227, 3, 149, 223, 3, 250, 231, 3, 244, 208, 3, 229, 223, 3, 177, 242, 3, 187, 211, 3, 141, 229, 3, 188, 219, 3, 162, 222, 3, 139, 246, 3, 205, 208, 3])
DEBUG:pc_ble_driver_py.observers:evt> on_gattc_evt_hvx status(BLEGattStatusCode.success) conn(0)
 error_handle(0)
 attr_handle(18)
 hvx_type(BLEGattHVXType.notification)
 data([0, 93, 98, 91, 10, 2, 24, 8, 16, 220, 131, 1, 42, 12, 0, 0, 29, 189, 0, 0, 172, 60, 0, 144, 123, 63, 50, 12, 41, 92, 143, 63, 246, 40, 60, 63, 113, 61, 170, 191, 61, 0, 152, 153, 65, 90, 48, 223, 211, 3, 227, 208, 3, 167, 209, 3, 243, 201, 3, 163, 227, 3, 192, 222, 3, 226, 231, 3, 244, 208, 3, 226, 223, 3, 184, 242, 3, 186, 211, 3, 130, 229, 3, 190, 219, 3, 160, 222, 3, 146, 246, 3, 207, 208, 3])

If I reduce the MTU on windows to 162, all data is sent and received correctly.

The code is exactly the same on windows and linux. I am using pc-ble-driver-py 0.14.1

Florian

[tesc]

Hi,

Throughput will vary between platforms, and so while running pc-ble-driver on linux may be fine with a given MTU and throughput, the same settings may not work on another platform. And vice versa.

How are you handling the situation where you get NRF_ERROR_RESOURCES from ble_nus_data_send()? Usually this is best handled by retrying, see e.g. the Handling data received over UART section of the documentation for the UART/Serial Port Emulation over BLE example. Note however that in that particular example we do a busy waiting loop, which is not good for power consumption.

The error means the TX buffer is full, so that more data cannot be queued. Instead of busy waiting you can retry after getting a BLE_EVT_TX_COPMPLETE event. There is some more information about the tx queue and NRF_ERROR_RESOURCES error code, as well as a suggestion for how the application can handle it, in the sd_ble_gatts_hvx() documentation.

Regards,
Terje

[Florian Zierer]

Hi Terje,

I do retries on the firmware side in this case. It works fine when sending the data to Android devices and sending to pc-ble-driver-py on linux. Just on Windows I get these errors.

It seems the notification is somehow disabled after some time or the connection gets somehow blocked.

How can I check on the firmware if the notification is still active?

I am checking for the BLE_NUS_EVT_COMM_STOPPED event, but didn't get one. So I think it should still be enabled but I don't get any BLE_NUS_EVT_TX_RDY any longer.

When notifications are enabled the BLE_NUS_EVT_COMM_STARTED is received correctly from my code.

I even debugged into on_hvx_tx_complete and checked if p_client->is_notification_enabled is still 1. It stays 1 but no more data can be enqueued so it seems the SD does not send the data out any longer.

Or how could I debug on the PC side?

I increased already the log_severity level to error ond these are the last messages I receive before it halts.

DEBUG:pc_ble_driver_py.observers:evt> on_gattc_evt_hvx status(BLEGattStatusCode.success) conn(0)
 error_handle(0)
 attr_handle(18)
 hvx_type(BLEGattHVXType.notification)
 data([0, 93, 98, 91, 10, 2, 24, 6, 16, 134, 202, 16, 42, 12, 0, 0, 8, 189, 0, 0, 206, 60, 0, 176, 121, 63, 50, 12, 246, 40, 188, 63, 184, 30, 197, 63, 113, 61, 170, 191, 61, 0, 224, 165, 65, 90, 48, 213, 211, 3, 215, 208, 3, 188, 209, 3, 238, 201, 3, 153, 227, 3, 213, 222, 3, 223, 231, 3, 239, 208, 3, 226, 223, 3, 177, 242, 3, 190, 211, 3, 140, 229, 3, 169, 219, 3, 155, 222, 3, 237, 245, 3, 202, 208, 3])
DEBUG:pc_ble_driver_py.ble_adapter:     185 ->  [N/A] type:                 ACK reliable: no seq#:0 ack#:5 payload_length:0 data_integrity:0 err_code:0x0
DEBUG:pc_ble_driver_py.observers:evt> severity(10) message(     185 ->  [N/A] type:                 ACK reliable: no seq#:0 ack#:5 payload_length:0 data_integrity:0 err_code:0x0)
DEBUG:pc_ble_driver_py.ble_adapter:  182/ 0 <-  [02 39 00 00 00 00 00 00 00 12 00 01 5f 00 00 5d 62 5b 0a 02 18 06 10 9a ca 10 2a 0c 00 00 12 bd 00 00 ce 3c 00 80 7c 3f 32 0c ae 47 a1 3f 66 66 86 3f 71 3d aa bf 3d 00 60 a4 41 5a 30 d3 d3 03 d9 d0 03 a2 d1 03 ed c9 03 9a e3 03 d2 de 03 dc e7 03 87 d1 03 e3 df 03 b2 f2 03 bf d3 03 8c e5 03 a5 db 03 9a de 03 84 f6 03 cd d0 03 ] type:     VENDOR_SPECIFIC reliable:yes seq#:5 ack#:4 payload_length:6d data_integrity:1 header_checksum:37 err_code:0x0
DEBUG:pc_ble_driver_py.observers:evt> severity(10) message(  182/ 0 <-  [02 39 00 00 00 00 00 00 00 12 00 01 5f 00 00 5d 62 5b 0a 02 18 06 10 9a ca 10 2a 0c 00 00 12 bd 00 00 ce 3c 00 80 7c 3f 32 0c ae 47 a1 3f 66 66 86 3f 71 3d aa bf 3d 00 60 a4 41 5a 30 d3 d3 03 d9 d0 03 a2 d1 03 ed c9 03 9a e3 03 d2 de 03 dc e7 03 87 d1 03 e3 df 03 b2 f2 03 bf d3 03 8c e5 03 a5 db 03 9a de 03 84 f6 03 cd d0 03 ] type:     VENDOR_SPECIFIC reliable:yes seq#:5 ack#:4 payload_length:6d data_integrity:1 header_checksum:37 err_code:0x0)
DEBUG:pc_ble_driver_py.observers:evt> on_gattc_evt_hvx status(BLEGattStatusCode.success) conn(0)
 error_handle(0)
 attr_handle(18)
 hvx_type(BLEGattHVXType.notification)
 data([0, 93, 98, 91, 10, 2, 24, 6, 16, 154, 202, 16, 42, 12, 0, 0, 18, 189, 0, 0, 206, 60, 0, 128, 124, 63, 50, 12, 174, 71, 161, 63, 102, 102, 134, 63, 113, 61, 170, 191, 61, 0, 96, 164, 65, 90, 48, 211, 211, 3, 217, 208, 3, 162, 209, 3, 237, 201, 3, 154, 227, 3, 210, 222, 3, 220, 231, 3, 135, 209, 3, 227, 223, 3, 178, 242, 3, 191, 211, 3, 140, 229, 3, 165, 219, 3, 154, 222, 3, 132, 246, 3, 205, 208, 3])
DEBUG:pc_ble_driver_py.ble_adapter:     186 ->  [N/A] type:                 ACK reliable: no seq#:0 ack#:6 payload_length:0 data_integrity:0 err_code:0x0
DEBUG:pc_ble_driver_py.observers:evt> severity(10) message(     186 ->  [N/A] type:                 ACK reliable: no seq#:0 ack#:6 payload_length:0 data_integrity:0 err_code:0x0)

I am using s140_nrf52_6.0.0_softdevice.hex with nrf SDK 15.0.0 on the firmware.

I also get randomly no answers from e.g. setting the MTU, or setting data length extension (also only on windows)

The messages are sent out, but I don't get a response (EvtSync.wait times out after 5 seconds and returns None).

Could this be the same issue or another one?

I tested from windows with a nrf52840 dongle and the nrf52840-dk and the nrf52832-dk. All three show the same behaviour (both issues).

[tesc]

Hi,

Are there any error codes in the log that are not reported as 0x00? Everything just halting with no error codes is not good, as it gives very little to work with.

A sniffer log will hopefully reveal more about what happens. Can you provide one?

Regards,
Terje

[Florian Zierer]

Hi Terje,

I did some more testing also with a sniffer and finally found out it was a timing issue on the windows side.

On windows the timeslice per process is 15.6ms and that's too long to react on e.g. 15ms or even 7.5ms connection intervals.

A workaround for me on windows is to use the "wres" python package to set the windows timer resolution to 1ms.

After this, all the errors seem to be gone.

Best,

Florian