How to see debug messages via RTT channel without running it from debugger?

[Harry]

I am working on an existing Bootloader project, it uses the Bootloader from the SDK with added custom thin layer on top of it. It runs on a custom board.

I can see the debug messages fine when I run it from the debugger (SEGGER J-Link) - on RTT channel (using J-Link RTT Viewer).

However, when I let it run standalone (with debugger connected to the board), I can only see debug messages from our custom code. Once it jumps into Bootloader SDK component, there is no debug messages anymore.

Did I miss some configuration in sdk_config.h? Or something else?

[Hung Bui]

Hi Serene, 
Maybe your issue is the same as this ? https://devzone.nordicsemi.com/f/nordic-q-a/20708/rtt-logging-from-application-started-by-bootloader

[Harry]

Thank you so much, Hung. I found that it's something with reset mechanism. It works ok now.

Btw, is it OK to ask you a side question? Or do you want me to post a new case?

Have you seen the flash erase operation interfering with DFU transfer? I know that the CPU is halted during flash erase. When I debug the Bootloader, the PC side (pc-nrfutil) didn't get a response for "CalcChecsum" command (sometimes at other places). And one time, I saw the debug message indicated it's doing "fstorage erase" operation. The problem is, when I run it from debugger, 99.9% of the time it worked fine - so I couldn't use breakpoints to step through.

[Hung Bui]

I don't have further idea except that you may need to run the bootloader in debug mode and check why it doesn't response to the CalcChecksum command. I suspect that it crashed earlier than that or it didn't receive the packet properly. 
But could you confirm that you only see the issue in 3 boards and only one board always failed ? When you test the other 2 board at 9600 would they also failed ? 

[Harry]

Hi Hung, 9600 still failed on one board. The other two work, but I need to test more to check.

The weird thing is, when it failed, the packet sequence is different, there are discrepancies. I used the same file, I don't understand why would the payload/sequence be any different, or why would it's parsed differently. It almost looks like the issue is in the file parsing.

Here's what I meant:

At the beginning:

At the end:

Let me know what you think.

[Hung Bui]

Hi Harry, 

Thanks for the trace. What I can see in the trace is that the main difference is the offset of 141 bytes in the Failed case. This showed that the bootloader already received the init packet and because of that the DFU master (I assume you are using nRFutil ? ) skip sending the init packet and simply execute it.

After that the DFU master continue to transfer the image until it finish the first object and ask for CRC check. The failed board didn't response to the request and on the retry it responded with the CRC of the init packet (exactly the same as in the first response to the init packet Select command at the beginning). So for some reason the bootloader didn't accept the first object of the application image. 

What I would suggest is to try to do a chip erase to clean the board and try again. Then you can record a trace with out the offset as in the current test. 

[Harry]

Hi Hung,

You're welcome. Yes, I use the python pc-nRFutil as the DFU master. Ok, I will try to do full chip erase and I will let you know.

I added the retry mechanism to the pc-nRFutil, so it seems that retry mechanism for checksum may not be ideal for this communication protocol, is that right?

I was wondering, does the bootloader store the last offset in bootloader settings - to be used to pick up where it left? I would imagine people may encounter this situation when a FW upgrade failed - then they won't be able to retry without doing full erase. Is there a recovery mechanism without full chip erase?

Ok, here is the result of the run. It went way pass the previous failure, but still it failed at similar operation of the board is not sending back any checksum. This is still running at 9600 bps. no HWFC.

(I removed the content, and replaced it with < <...... lots of data here ........> >)

2020-08-27 12:51:49,808 Sending Application image.
2020-08-27 12:51:52,812 SLIP: --> [9, 1]
2020-08-27 12:51:52,822 SLIP: <-- [2, 2, 126, 96, 9, 1, 1]
2020-08-27 12:51:52,822 Serial: No Response: 0x02
2020-08-27 12:51:52,822 SLIP: --> [9, 2]
2020-08-27 12:51:52,832 SLIP: <-- [96, 9, 1, 2]
>> Ping resp
2020-08-27 12:51:52,834 Serial: Set Packet Receipt Notification 0
2020-08-27 12:51:52,834 SLIP: --> [2, 0, 0]
2020-08-27 12:51:52,842 SLIP: <-- [96, 2, 1]
2020-08-27 12:51:52,845 SLIP: --> [7]
2020-08-27 12:51:52,855 SLIP: <-- [96, 7, 1, 131, 0]
MTU recv: 131
2020-08-27 12:51:52,858 Sending init packet...
2020-08-27 12:51:52,858 Serial: Selecting Object: type:1
2020-08-27 12:51:52,858 SLIP: --> [6, 1]
2020-08-27 12:51:52,881 SLIP: <-- [96, 6, 1, 0, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2020-08-27 12:51:52,881 Serial: Object selected:  max_size:512 offset:0 crc:0
2020-08-27 12:51:52,881 SLIP: --> [1, 1, 141, 0, 0, 0]
2020-08-27 12:51:52,894 SLIP: <-- [96, 1, 1]
2020-08-27 12:51:52,895 Serial: Streaming Data: len:141 offset:0 crc:0x00000000
2020-08-27 12:51:52,895 SLIP: --> [8, 18, 138, 1, 10, 68, 8, 1, 18, 64, 8, 1, 16, 52, 26, 2, 182, 1, 32, 0, 40, 0, 48, 0, 56, 248, 143, 14, 66, 36, 8, 3, 18, 32, 179, 191, 14, 64, 59, 56, 142, 105, 59, 100, 116, 179, 191, 246, 154, 86, 58, 54, 37, 227, 123, 44, 21, 249, 120, 157, 3, 54, 174, 213, 180]
2020-08-27 12:51:52,897 SLIP: --> [8, 67, 72, 0, 82, 4, 8, 1, 18, 0, 16, 0, 26, 64, 232, 222, 197, 26, 1, 55, 172, 224, 122, 238, 104, 172, 203, 121, 70, 131, 219, 205, 239, 224, 86, 1, 61, 17, 117, 22, 221, 152, 255, 186, 96, 113, 239, 230, 14, 19, 214, 237, 30, 20, 176, 230, 128, 15, 223, 103, 11, 93, 76, 69, 131]
2020-08-27 12:51:52,897 SLIP: --> [8, 153, 37, 0, 229, 169, 43, 43, 110, 207, 147, 120, 171, 68]
2020-08-27 12:51:52,898 SLIP: --> [3]
2020-08-27 12:51:53,065 SLIP: <-- [96, 3, 1, 141, 0, 0, 0, 195, 20, 20, 217]
2020-08-27 12:51:53,306 Sending firmware file...
2020-08-27 12:51:53,308 Serial: Selecting Object: type:2
2020-08-27 12:51:53,308 SLIP: --> [6, 2]
2020-08-27 12:51:53,331 SLIP: <-- [96, 6, 1, 0, 16, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
2020-08-27 12:51:53,332 Serial: Object selected:  max_size:4096 offset:0 crc:0
2020-08-27 12:51:53,332 SLIP: --> [1, 2, 0, 16, 0, 0]
2020-08-27 12:51:53,430 SLIP: <-- [96, 1, 1]
2020-08-27 12:51:53,430 Serial: Streaming Data: len:4096 offset:0 crc:0x00000000
2020-08-27 12:51:53,431 SLIP: --> [8, 16, 219, 3, 32, 177, 100, 2, 0, 185, 100, 2, 0, 187, 100, 2, 0, 189, 100, 2, 0, 191, 100, 2, 0, 193, 100, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 195, 100, 2, 0, 197, 100, 2, 0, 0, 0, 0, 0, 199, 100, 2, 0, 201, 100, 2, 0]

<<...... lots of data here ........>>

2020-08-27 12:51:57,322 SLIP: --> [8, 3, 10, 180, 238, 224, 10, 241, 238, 16, 250, 19, 216, 0, 32, 9, 235, 1, 18, 0, 191, 0, 235, 133, 3, 7, 235, 131, 3, 147, 237, 0, 10, 189, 238, 192, 10, 16, 238, 16, 58, 66, 248, 32, 48, 64, 28, 3, 40, 240, 221, 73, 28, 2, 41, 125, 209, 6, 153, 8, 152, 8, 154, 65, 26]
2020-08-27 12:51:57,394 SLIP: --> [3]
2020-08-27 12:51:57,882 SLIP: <-- [96, 3, 1, 0, 16, 0, 0, 122, 195, 171, 203]
This is response from __calculate_checksum
[0, 16, 0, 0, 122, 195, 171, 203]
2020-08-27 12:51:57,890 SLIP: --> [4]
2020-08-27 12:51:57,898 SLIP: <-- [96, 4, 1]
2020-08-27 12:51:57,904 SLIP: --> [1, 2, 0, 16, 0, 0]
2020-08-27 12:51:58,003 SLIP: <-- [96, 1, 1]
2020-08-27 12:51:58,003 Serial: Streaming Data: len:4096 offset:4096 crc:0xCBABC37A
2020-08-27 12:51:58,005 SLIP: --> [8, 10, 152, 128, 26, 64, 28, 73, 28, 109, 212, 0, 40, 107, 219, 3, 144, 6, 154, 31, 152, 0, 235, 130, 0, 8, 240, 98, 255, 8, 153, 31, 152, 240, 238, 64, 154, 0, 235, 129, 0, 3, 153, 8, 240, 187, 254, 241, 238, 73, 10, 32, 238, 32, 10, 244, 238, 192, 154, 241, 238, 16, 250, 82, 210]

<<...... lots of data here ........>>

2020-08-27 12:52:01,921 SLIP: --> [8, 66, 246, 34, 33, 1, 224, 66, 246, 33, 33, 161, 34, 42, 112, 10, 10, 234, 112, 41, 113, 144, 248, 66, 16, 105, 113, 176, 248, 68, 32, 5, 38, 81, 28, 160, 248, 68, 16, 17, 10, 169, 113, 234, 113, 5, 241, 8, 4, 0, 34, 38, 224, 2, 235, 66, 7, 0, 33, 0, 235, 135, 12, 0, 191]
2020-08-27 12:52:01,989 SLIP: --> [3]
2020-08-27 12:52:01,992 SLIP: <-- [0, 96, 192, 2]
Traceback (most recent call last):
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\board_prog.py", line 29, in <module>
    run()
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\click\core.py", line 828, in __call__
    return self.main(*args, **kwargs)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\click\core.py", line 781, in main
    rv = self.invoke(ctx)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\click\core.py", line 1046, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\click\core.py", line 590, in invoke
    return callback(*args, **kwargs)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\board_prog.py", line 25, in run
    dfu.flash(package, rlevel)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\mdfu.py", line 178, in flash
    dfu.dfu_send_images()
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\nordicsemi\dfu\dfu.py", line 129, in dfu_send_images
    self._dfu_send_image(self.manifest.application)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\nordicsemi\dfu\dfu.py", line 102, in _dfu_send_image
    self.dfu_transport.send_firmware(data)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\nordicsemi\dfu\dfu_transport_serial.py", line 327, in send_firmware
    response['crc'] = self.__stream_data(data=data, crc=response['crc'], offset=i)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\nordicsemi\dfu\dfu_transport_serial.py", line 530, in __stream_data
    response = self.__calculate_checksum()
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\nordicsemi\dfu\dfu_transport_serial.py", line 456, in __calculate_checksum
    DfuTransportSerial.OP_CODE['CalcChecSum'])
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\nordicsemi\dfu\dfu_transport_serial.py", line 539, in __send_get_response
    resp = self.__get_response(operation, listresp)
  File "H:\Projects\Nordic\nRFBoot\PyTool\nrfUtil_6.1\lib\nordicsemi\dfu\dfu_transport_serial.py", line 566, in __get_response
    raise NordicSemiException('No Response: 0x{:02X}'.format(resp[0]))
pc_ble_driver_py.exceptions.NordicSemiException: No Response: 0x00

[Hung Bui]

Hi Harry, 
The response code [0, 96, 192, 2] is a little bit strange to me. When it started with a 0 and 192 doesn't really match the response code as far as I remember. 
There must be something wrong with the bootloader. If it's possible to debug the bootloader to check why it send such response we would be able to figure out. 
In addition the response code came just 3uS after the CRC request also suggested that there must be something wrong. Usually the CRC calculation takes a few hundred micro seconds. 

I'm thinking og there is a chance that there's been a RAM/Flash hardware issue.

[Harry]

Ok Hung, I will try to debug it. If I recall correctly, it worked fine when it runs from debugger. I'll let you know.

In the meantime, would you mind giving me the answer of these questions?

Harry said:

I added the retry mechanism to the pc-nRFutil, so it seems that retry mechanism for checksum may not be ideal for this communication protocol, is that right?

I was wondering, does the bootloader store the last offset in bootloader settings - to be used to pick up where it left? I would imagine people may encounter this situation when a FW upgrade failed - then they won't be able to retry without doing full erase. Is there a recovery mechanism without full chip erase?

[Hung Bui]

Hi Harry, 

Could you let me know the SDK version of your bootloader ? 

Our current bootloader does support recovery mechanism and the offset value is stored in the bootloader setting. 

I have tried this on BLE DFU but it should operate the same on UART DFU (if implemented properly in nrfutil). 

[Harry]

Hi Hung,

The SDK I use is V15.3.0.

[Hung Bui]

Hi Harry, 
If you use bootloader in SDK v15.3 the resume feature should already be implemented. You can find in the nrf_dfu_settings_t struct in nrf_dfu_types.h the write_offset property. It's the current offset of the part of image that it's already received. This value is sent to the DFU master when it start the process. And it's stored in flash.