Hi, I am using pc-ble-driver v4.1.4 combined with connectivity firmware compiled with s132 v6.1.1. My application is running on custom hardware with a cp210x serial to usb converter to communicate with an nrf52832. The board runs openwrt on MIPS architecture.
For the most part normal connections, discovery, scanning, etc, all run smoothly with only a few errors every now and then. However, I have started to run into weird problems while implementing the nordic dfu protocol over bluetooth. The snippet below shows some of the logs with the issue:
I20211129 16:51:31.302917 3249 dfu_transport.cpp:413] Got response: 600101 I20211129 16:51:31.303856 3249 dfu_transport.cpp:342] Streaming data: len=4096 offset=114688 crc=4ced6b02 I20211129 16:51:31.304706 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:31.311787 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:31.312841 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:31.822641 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:31.823949 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:31.825325 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:32.084010 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:32.085310 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:32.086726 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:32.095208 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:32.096516 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:32.098080 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:32.356534 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:32.357832 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:32.359284 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:32.617930 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:32.619302 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:32.620904 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:32.628456 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:32.629909 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:32.888808 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:32.890456 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:32.891034 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:32.892475 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:33.151417 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:33.152993 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:33.154599 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:33.413298 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:33.415063 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:33.416580 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:33.424257 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:33.425621 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:33.684623 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:33.685932 3245 link_ctx_mgr.cpp:226] Write cmd tx event for link idx 0 I20211129 16:51:33.687680 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:33.946646 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:33.948005 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:33.955822 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:33.957233 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:34.216219 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:34.217581 3249 dfu_transport.cpp:351] Writing 244 bytes to data point I20211129 16:51:34.225050 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:34.226095 3249 dfu_transport.cpp:351] Writing 192 bytes to data point I20211129 16:51:34.483803 3249 gatt_queue.cpp:34] Executing write cmd err=0 I20211129 16:51:34.487776 3249 gatt_queue.cpp:34] Executing write request err=0 I20211129 16:51:34.489153 3249 dfu_transport.cpp:403] Waiting for response for op: 3 E20211129 16:51:44.490528 3249 dfu_transport.cpp:408] Did not get response I20211129 16:51:44.503031 3249 dfu_operation.cpp:68] [d5:6a:bb:bd:90:cf] entered state RETRYING E20211129 16:51:44.509176 3249 dfu_operation.cpp:103] Error doing dfu: An error occurred during the dfu
You can see all of the write commands / requests being sent here. The weird part is that eventually I stop receiving write command tx confirmations and there is no indication that the device has disconnected or that the UART transport has stopped working. Every softdevice call succeeds returning NRF_SUCCESS but to me it seems like events are being dropped. I try to handle this error by calling sd_ble_gap_disconnect which also returns NRF_SUCCESS but I got no disconnection event from the soft device handler. However, I see my device advertising DFU_TARG which means the disconnect was successful. Also I start scanning after this error but receive no scan events.
I am not really sure whats really going on here and don't have a clear path for debugging this. It's also worth noting that when I run the same application on a development environment (computer connected to nordic PCA10040) everything runs flawlessly.
