Serial DFU bootloader example - "No ping response after opening COM port"

[FranzKnut]

Hi,

We are trying to get the serial dfu example from sdk 14.2 working with an nrf52832. After flashing the device succesfully and starting up the bootloader we were unable to initiate a transfer via UART. nrfutil produces the following error message:

#  nrfutil dfu serial -pkg firmware.zip -p /dev/tty.usbmodemFA1321 -b 115200 -fc 1
[------------------------------------]    0%
Traceback (most recent call last):
  File "/usr/local/bin/nrfutil", line 11, in <module>
    sys.exit(cli())
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 722, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 697, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 1066, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 1066, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 895, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 535, in invoke
    return callback(*args, **kwargs)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/__main__.py", line 741, in serial
    do_serial(package, port, connect_delay, flow_control, packet_receipt_notification, baud_rate, True)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/__main__.py", line 676, in do_serial
    dfu.dfu_send_images()
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu.py", line 129, in dfu_send_images
    self._dfu_send_image(self.manifest.application)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu.py", line 90, in _dfu_send_image
    self.dfu_transport.open()
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_serial.py", line 211, in open
    raise NordicSemiException("No ping response after opening COM port")
pc_ble_driver_py.exceptions.NordicSemiException: No ping response after opening COM port

After adding NRF_LOG to the example the following debug messages showed up in the SES RTT-client:

<info> app: Inside main
<debug> app: In nrf_bootloader_init
<debug> app: in weak nrf_dfu_init_user
<debug> app: In real nrf_dfu_init
<debug> nrf_dfu_settings: Running nrf_dfu_settings_init(sd_irq_initialized=false).
<debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> app: Initializing the clock.
<debug> app: Enter nrf_dfu_continue
<debug> app: Valid App
<debug> app: Enter nrf_dfu_app_is_valid
<debug> app: Return true. App was valid
<debug> app: In nrf_dfu_transports_init
<debug> app: num transports: 1
<info> uart: RX Id:2 len:1
<debug> app: UART initialized
<debug> app: After nrf_dfu_transports_init
<debug> nrf_dfu_flash: Calling nrf_dfu_flash_init(sd_irq_initialized=false)...
<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.
<debug> app: Waiting for events
<debug> app: UART RX done
<info> uart: RX Id:2 len:1
<debug> app: UART RX done
<info> uart: RX Id:2 len:1
<debug> app: UART RX done
<debug> app: Received ping 1
<debug> app: Sending Response: [0x9, 0x1]
<info> uart: TX req id:2 length: 5.
<info> uart: RX Id:2 len:1

We are on OS X using SES Version 3.34b and nrfutil 3.5.0 with python 2.7.14.

Even when using the precompiled example images located in /examples/dfu/secure_dfu_test_images/serial/nrf52832 we get the same error messages.

Any help is appreciated!

Regards, Julian

[FranzKnut]

I managed to go a bit further by disabling HWFC in nrf_serial_dfu. However I am now stuck with the following error message (I already tried to use a low baudrate but with no success):

 # nrfutil dfu serial -pkg $PACKAGE -p $PORT -b 57600
  [------------------------------------]    0%
Traceback (most recent call last):
  File "/usr/local/bin/nrfutil", line 11, in <module>
    sys.exit(cli())
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 722, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 697, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 1066, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 1066, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 895, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python2.7/site-packages/click/core.py", line 535, in invoke
    return callback(*args, **kwargs)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/__main__.py", line 745, in serial
    do_serial(package, port, connect_delay, flow_control, packet_receipt_notification, baud_rate, True)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/__main__.py", line 680, in do_serial
    dfu.dfu_send_images()
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu.py", line 129, in dfu_send_images
    self._dfu_send_image(self.manifest.application)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu.py", line 97, in _dfu_send_image
    self.dfu_transport.send_init_packet(data)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_serial.py", line 244, in send_init_packet
    response = self.__select_command()
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_serial.py", line 373, in __select_command
    return self.__select_object(0x01)
  File "/usr/local/lib/python2.7/site-packages/nordicsemi/dfu/dfu_transport_serial.py", line 383, in __select_object
    (max_size, offset, crc)= struct.unpack('<III', bytearray(response))
struct.error: unpack requires a string argument of length 12

[Jørgen Holmefjord]

Did you try this with one of the DFU test packets from the SDK, or only with your own pack?

[FranzKnut]

I tried now but got the same results.

[Jørgen Holmefjord]

Do your board have HWFC pins? Did you disable FC in the bootloader code? How low baudrate did you try?

Most likely the response is not received properly. Can you add a debug output to the Python code, checking what the content of response is?

[FranzKnut]

By disabling FC in the bootloader code I got to where I am right now. The lowest baudrate I tried was 19200. Below that the original "No ping response" message reappeared.

I added the following line to the python script:

response = self.__get_response(DfuTransportSerial.OP_CODE['ReadObject'])
logger.debug("Response: {}".format(response))
        
(max_size, offset, crc)= struct.unpack('<III', bytearray(response))

When invocing the script with verbose output I got the following:

2018-08-16 17:22:21,053 Using board at serial port: /dev/tty.usbmodemFA1341
2018-08-16 17:22:21,061 Sending Application image.
2018-08-16 17:22:24,066 SLIP: --> [9, 1]
2018-08-16 17:22:24,074 SLIP: <-- [96, 9, 1, 1]
2018-08-16 17:22:25,077 Serial: Set Packet Receipt Notification 0
2018-08-16 17:22:25,077 SLIP: --> [2, 0, 0]
2018-08-16 17:22:25,084 SLIP: <-- [96, 2, 1]
2018-08-16 17:22:25,085 SLIP: --> [7]
2018-08-16 17:22:25,092 SLIP: <-- [96, 7, 1, 129, 0]
2018-08-16 17:22:25,092 Sending init packet...
2018-08-16 17:22:25,093 Serial: Selecting Object: type:1
2018-08-16 17:22:25,093 SLIP: --> [6, 1]
2018-08-16 17:22:25,101 SLIP: <-- [96, 6, 1, 0]
2018-08-16 17:22:25,102 Response: [0]

(plus after that the same traceback as above)

[FranzKnut]

I was able to fix it and may have found a bug in nrf_serial_dfu.c (?):

I had to increase MAX_RESPONSE_SIZE by one. Then it worked when using a low Baudrate of 14400.

Best regards,

Julian