DFU via nrfutil is taking longer to start on our custom board than it does on the nRF52840-Preview-DK board

[DBT]

I tried out DFU functionality initially using nRF52840-PreviewDK and UART transport

When downloading an app via DFU, It takes about 6 seconds from the time I start nrfutil until the progress bar shows.

Now I've ported DFU code over to our custom board and it takes about 35 seconds from the time I start nrfutil until the progress bar shows.

Why is it taking so much longer to start on our custom board?

To be clear, the DFU download works on our board and I can confirm that the app is running after DFU download.

I just don't understand why nrfutil is taking longer to start.  I confirmed with a scope that nrfutil doesn't start sending data over the UART until after about 35 seconds, and our custom board responds to the initial message within about 50 microseconds, so it's not like nrfutil is pinging our board and its taking our board longer to start responding.  It seems like its something happening in nrfutil rather than in the bootloader on our board.

Our board does not use flow control, so I use the "-fc 0" command line option: nrfutil dfu serial -pkg app_dfu_package.zip -p COM13 -b 115200 -fc 0

The nRF52840-PreviewDK board apparently does use flow control, but I tried using "-fc 0" when downloading to the nRF52840-PreviewDK board and it didn't appear to affect the start time.

Do you have any insights on this issue?

[Einar Thorsrud]

Hi,

I don't have an explanation at this point, but it seems strange. Serial DFU can use retransmission on the application layer, so it could be that there is a log of data corruption, making it take a long time. it seems like a long shot, though.

Some questions:

• When you test with a logic analyzer, how does is the activity on the UART lines? Is there no activity for all those idle seconds in the initial phase?
• Have you tested simple UART communication (not DFU)?
  • Could there be some issue with the UART lines causing unstable communication?
  • Can you make sure to request the HF clock so that we know that the issue is not caused by an inaccurate clock in the nRF (the high-frequency RC oscillator has a too high tolerance for UART, so it could cause communication problems if you are unlucky).

[DBT]

I am able to reproduce this issue using a nRF52840-Preview-DK board where I use a separate USB-to-UART adapter/cable.  I tried both a cable from FTDI and a generic USB-to-UART adapter board that has a Silabs CP2102 chip on it.  Both worked to reproduce the 35-second startup delay, but the instructions below (specifically the wire colors) are for the FTDI cable.

1. I’m using FTDI cable TTL-2332RG-VIP-WE: https://www.ftdichip.com/Products/Cables/USBTTLSerial.htm
   1. Could also use TTL-232RG-VREG3V3-WE or TTL-232R-3V3 or TTL-232R-3V3-PCB or any USB-to-UART adapter that works at 3.3V on the UART side.
   2. Black wire = GND.  Connect to connector P1 pin 7 on the Preview-DK board
   3. Red wire = VDD.  Connect to connector P1 pin 1
   4. Orange wire = UART TX (transmit from PC to Nordic).  Connect to connector P6 pin 6 (marked P0.08 on the silkscreen)
   5. Yellow wire = UART RX (receive from Nordic to PC).  Connect to connector P6 pin 4 (marked P0.06 on the silkscreen)
2. Connect powered USB cable to J3 (marked nRF USB on the silkscreen)
3. Press and hold button 4 while toggling SW8 (marked Power on the silkscreen) from off to on. (to put it in DFU mode)
4. Use nrfutil to try to download an app (I used “nrfutil dfu serial -pkg ble_blinky_app_dfu_package_u.zip -p COM13 -b 115200 -fc 0” where COM13 corresponds to the FTDI cable)

This works to reproduce the 35-second startup delay.  The DFU download of the app works, but it takes about 35 seconds before any activity is seen on the UART lines.

This looks like an nrfutil issue.  It appears this happens whenever the UART connection has no flow control, even when the "-fc 0" option is used with nrfutil.

Please look into it and provide a solution ASAP.

[Einar Thorsrud]

Hi,

Unfortunately, I don't have a USB-serial converter at hand, so I have not been able to test today.

I am not sure you can conclude this is a nrfutil issue. Nrfutil is just a python script and is itself independent of the USB-serial bridge, though there could be some lower-level differences in the driver or similar.

It would be interesting to get some more information. Can you repeat the test with debug logging enabled in nrfutil? You can enable it by editing C:\Python27\Lib\site-packages\nordicsemi\dfu\dfu_transport_serial.py (assuming you use Windows), adding the following on line 63 (below the instantiation of the logger):

logger.setLevel(logging.DEBUG)

Please upload the log here.

[DBT]

I have windows, but C:\Python27\Lib\site-packages\nordicsemi\dfu\dfu_transport_serial.py doesn't exist on my PC.  

dfu_transport_serial.py isn't anywhere on my PC.

C:\Python27\Lib\site-packages does not have a nordicsemi subdirectory.

Do I need to install something?

[Einar Thorsrud]

Hi,

The path was based on a few assumptions. It would be there if you are using nrfutil on a windows PC, and have Pything installed in C:\Python27 and installed nrfutil using pip. You will not find the dfu_transport_serial.py file if you are using a nrfutil that has been packaged as a .exe file.

Can you try to install the latest nrfutil via pip? Please note that nrfutil requires python 2 (not 3). When you have python 2 installed you can call "pip2 install nrfutil" to install it. Then you will get the newest nrfutil (5.2.0) as a python script and it will automatically be in your path. Now you can do the change I suggested (adjust for any difference in where Python is in your system), and you will get a lot of logs during the DFU process.

[DBT]

This is what comes up in the terminal window:

C:\nordic\nRF5_SDK_15.3.0_59ac345\nRF5SDK153059ac345\nRF5_SDK_15.3.0_59ac345\examples\ble_peripheral\ble_app_blinky\pca10056\s140\ses\Output\Release\Exe>nrfutil dfu serial -pkg ble_blinky_app_dfu_package.zip -p COM13 -b 115200 -fc 0
2019-08-08 09:47:14,815 Serial: Set Packet Receipt Notification 0
2019-08-08 09:47:14,848 Serial: Selecting Object: type:1
2019-08-08 09:47:14,864 Serial: Object selected: max_size:512 offset:0 crc:0
2019-08-08 09:47:14,880 Serial: Streaming Data: len:141 offset:0 crc:0x00000000
2019-08-08 09:47:15,072 Serial: Selecting Object: type:2
2019-08-08 09:47:15,088 Serial: Object selected: max_size:4096 offset:0 crc:0
2019-08-08 09:47:15,198 Serial: Streaming Data: len:4096 offset:0 crc:0x00000000
[######------------------------------] 18% 00:02:312019-08-08 09:47:15,694 Serial: Streaming Data: len:4096 offset:4096 crc:0xA0E6B9DD
[#############-----------------------] 36% 00:01:572019-08-08 09:47:16,190 Serial: Streaming Data: len:4096 offset:8192 crc:0xC10085B8
[###################-----------------] 54% 00:01:232019-08-08 09:47:16,686 Serial: Streaming Data: len:4096 offset:12288 crc:0x64C25F08
[##########################----------] 73% 00:00:312019-08-08 09:47:17,181 Serial: Streaming Data: len:4096 offset:16384 crc:0xCB18C2BA
[################################----] 91% 00:00:092019-08-08 09:47:17,665 Serial: Streaming Data: len:1884 offset:20480 crc:0x3F1CF308
[####################################] 100%
Device programmed.

That's more detail than normally shows during the DFU process.

Is that what you wanted or is there a log file somewhere you're looking for?

[Einar Thorsrud]

Hi,

That was the log I was thinking about. Looking at the timestamps it doe snot look like this took more than a few seconds. Do you have a similar log output from when you see the problem?