Thread Secure DFU Example not working on nRF5 SDK for Thread and Zigbee v1.0.0

[kristofbo]

Hi,

This is a follow up of issue: https://devzone.nordicsemi.com/f/nordic-q-a/28211/thread-dfu-upgrade-problems/111436

We're trying to perform DFU by following "Thread Secure DFU Example" on nRF5 SDK for Thread and Zigbee v1.0.0, but still with no success.

Here are some details regarding my environment:

$ uname -a
Linux krzysiek 4.10.0-40-generic #44-Ubuntu SMP Thu Nov 9 14:49:09 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux


$ python --version
Python 2.7.14


$ pip list
nrfutil (3.5.0)
pyspinel (1.0.0a1)

The bahaviour is the same like in aforementioned issue, i.e.:
Board with the client is able to send trigger packet request to NCP/DFU server board, nrfutil sees the request, prints message about sending the reply, but reply never reaches client, ping works, router table shows both devices, etc.

Logs from nrfutil:

10:45 $ sudo nrfutil -v -v -v -v dfu thread -f -pkg app_dfu_package.zip -snr 683508087 --channel 11 --panid 43981
2018-04-25 10:45:14,534 Shared library: /home/krzysiek/.local/lib/python2.7/site-packages/pc_ble_driver_py/lib/linux/x86_64/libpc_ble_driver_shared_sd_api_v3.so
2018-04-25 10:45:14,534 Swig module name: pc_ble_driver_sd_api_v3
Address not specified. Using ff03::1 (all Thread nodes)
Using connectivity board at serial port: /dev/ttyACM1
Board already flashed with connectivity firmware.
2018-04-25 10:45:20,010 Image type application found
2018-04-25 10:45:20,011 Attaching to the network
2018-04-25 10:45:20,011 Setting property PROP_IPv6_ICMP_PING_OFFLOAD to 1
2018-04-25 10:45:20,012 
Property Unknown (5389): 
2018-04-25 10:45:20,014 Done
2018-04-25 10:45:20,015 Setting property PROP_THREAD_RLOC16_DEBUG_PASSTHRU to 1
2018-04-25 10:45:20,018 Done
2018-04-25 10:45:20,018 Setting property PROP_PHY_CHAN to 11
2018-04-25 10:45:20,021 Done
2018-04-25 10:45:20,022 Setting property PROP_MAC_15_4_PANID to 43981
2018-04-25 10:45:20,025 Done
2018-04-25 10:45:20,025 Setting property PROP_NET_IF_UP to 1
2018-04-25 10:45:20,029 Done
2018-04-25 10:45:20,029 Setting property PROP_NET_STACK_UP to 2
2018-04-25 10:45:20,032 Done
2018-04-25 10:45:21,195 
Property Unknown (5389): 
2018-04-25 10:45:22,060 Done
2018-04-25 10:45:22,060 NCP Thread IPv6 addresses:
2018-04-25 10:45:22,076 fdde:ad00:beef::ff:fe00:c01
2018-04-25 10:45:22,076 fdde:ad00:beef:0:345c:52be:c8e4:a3eb
2018-04-25 10:45:22,076 fe80::b4d1:6f05:9a5c:e29c
Waiting for NCP to promote to a router...
2018-04-25 10:45:28,083 Triggering DFU on Endpoint(addr=IPv6Address(u'ff03::1'), port=5683)
2018-04-25 10:45:28,085 Sending message to ff03::1:5683
2018-04-25 10:45:28,089 Sending datagram fdde:ad00:beef::ff:fe00:7800 5683 ff03::1 5683
2018-04-25 10:45:28,090 Message 'R\x02\x03\xec\xd2+\xb1t\xff\x10\x00\x00\x00\x86\xc9\xebH\x1f\x00\x05\x05\x88>\x02\x8c2' sent successfully
2018-04-25 10:45:28,091 Sending request - Token: d22b, Host: ff03::1, Port: 5683
Thread DFU server is running... Press <Ctrl + C> to stop.
2018-04-25 10:45:30,091 Request timed out
2018-04-25 10:45:30,091 Exchange removed, Message ID: 1004.
2018-04-25 10:45:30,091 Sending message to ff03::1:5683
2018-04-25 10:45:30,123 Sending datagram fdde:ad00:beef::ff:fe00:7800 5683 ff03::1 5683
2018-04-25 10:45:30,124 Message 'R\x02\x03\xec\xd2+\xb1t\xff\x10\x00\x00\x00\x86\xc9\xebH\x1f\x00\x05\x05\x88>\x02\x8c2' sent successfully
2018-04-25 10:45:30,124 Sending request - Token: d22b, Host: ff03::1, Port: 5683
2018-04-25 10:45:32,124 Request timed out
2018-04-25 10:45:32,125 Exchange removed, Message ID: 1004.
2018-04-25 10:45:32,125 Sending message to ff03::1:5683
2018-04-25 10:45:32,157 Sending datagram fdde:ad00:beef::ff:fe00:7800 5683 ff03::1 5683
2018-04-25 10:45:32,158 Message 'R\x02\x03\xec\xd2+\xb1t\xff\x10\x00\x00\x00\x86\xc9\xebH\x1f\x00\x05\x05\x88>\x02\x8c2' sent successfully
2018-04-25 10:45:32,159 Sending request - Token: d22b, Host: ff03::1, Port: 5683
2018-04-25 10:45:34,159 Request timed out
2018-04-25 10:45:34,159 Exchange removed, Message ID: 1004.
2018-04-25 10:45:55,292 Received 'R\x01yO\t_\xb1t' from fdde:ad00:beef::ff:fe00:c00:5683
2018-04-25 10:45:55,292 Incoming Message ID: 31055
2018-04-25 10:45:55,292 New unique CON or NON message received
2018-04-25 10:45:55,295 Preparing response...
2018-04-25 10:45:55,295 Token: 09:5f
2018-04-25 10:45:55,295 Sending response, type = ACK (request type = NON)
2018-04-25 10:45:55,295 Sending message to fdde:ad00:beef::ff:fe00:c00:5683
2018-04-25 10:45:55,296 Sending datagram fdde:ad00:beef:0:345c:52be:c8e4:a3eb 5683 fdde:ad00:beef::ff:fe00:c00 5683
2018-04-25 10:45:55,297 Message 'bEyO\t_\xff\x10\x00\x00\x00\x86\xc9\xebH\x1f\x00\x05\x05\x88>\x02\x8c2' sent successfully
2018-04-25 10:46:26,054 Received 'R\x01yPX\xd2\xb1t' from fdde:ad00:beef::ff:fe00:c00:5683
2018-04-25 10:46:26,054 Incoming Message ID: 31056
2018-04-25 10:46:26,055 New unique CON or NON message received
2018-04-25 10:46:26,057 Preparing response...
2018-04-25 10:46:26,057 Token: 58:d2
2018-04-25 10:46:26,057 Sending response, type = ACK (request type = NON)
2018-04-25 10:46:26,057 Sending message to fdde:ad00:beef::ff:fe00:c00:5683
2018-04-25 10:46:26,057 Sending datagram fdde:ad00:beef:0:345c:52be:c8e4:a3eb 5683 fdde:ad00:beef::ff:fe00:c00 5683
2018-04-25 10:46:26,058 Message 'bEyPX\xd2\xff\x10\x00\x00\x00\x86\xc9\xebH\x1f\x00\x05\x05\x88>\x02\x8c2' sent successfully
2018-04-25 10:46:57,034 Received 'R\x01yQ\x00\xb4\xb1t' from fdde:ad00:beef::ff:fe00:c00:5683
2018-04-25 10:46:57,034 Incoming Message ID: 31057
2018-04-25 10:46:57,034 New unique CON or NON message received
2018-04-25 10:46:57,037 Preparing response...
2018-04-25 10:46:57,037 Token: 00:b4
2018-04-25 10:46:57,037 Sending response, type = ACK (request type = NON)
2018-04-25 10:46:57,037 Sending message to fdde:ad00:beef::ff:fe00:c00:5683
2018-04-25 10:46:57,037 Sending datagram fdde:ad00:beef:0:345c:52be:c8e4:a3eb 5683 fdde:ad00:beef::ff:fe00:c00 5683
2018-04-25 10:46:57,038 Message 'bEyQ\x00\xb4\xff\x10\x00\x00\x00\x86\xc9\xebH\x1f\x00\x05\x05\x88>\x02\x8c2' sent successfully

Logs from DFU client:

<info> app: Thread version: OPENTHREAD/20170716-00532-gec59d7e-dirty; NRF52840; Apr  6 2018 23:55:28
<info> app: Network name:   OpenThread
<info> app: Thread interface has been enabled.
<info> app: 802.15.4 Channel: 11
<info> app: 802.15.4 PAN ID:  0xABCD
<info> app: rx-on-when-idle:  enabled
<info> COAP_DFU: Endpoints initialized
<info> background_dfu: Current DFU Diag version: Apr 25 2018 09:31:36, 0x9C741A3D
<info> app: 

<info> app: 

<info> app: 

<info> app: New role: 1

<info> app: New role: 4

<info> COAP_DFU: Triggering DFU
<info> background_dfu: state=DFU_IDLE event=DFU_EVENT_TRANSFER_COMPLETE
<info> COAP_DFU: Requesting [t] (block:0 mid:31055)
<warning> COAP_DFU: Request timeout
<info> background_dfu: state=DFU_DOWNLOAD_TRIG event=DFU_EVENT_TRANSFER_ERROR
<info> COAP_DFU: Requesting [t] (block:0 mid:31056)
<warning> COAP_DFU: Request timeout
<info> background_dfu: state=DFU_DOWNLOAD_TRIG event=DFU_EVENT_TRANSFER_ERROR
<info> COAP_DFU: Requesting [t] (block:0 mid:31057)
<warning> COAP_DFU: Request timeout
<info> background_dfu: state=DFU_DOWNLOAD_TRIG event=DFU_EVENT_TRANSFER_ERROR
<error> background_dfu: No more retries
<info> background_dfu: Current DFU Diag version: Apr 25 2018 09:31:36, 0x9C741A3D

Logs from DFU client CLI:

> ipaddr
fdde:ad00:beef:0:0:ff:fe00:fc00
fdde:ad00:beef:0:0:ff:fe00:c00
fe80:0:0:0:841f:6835:2b1e:a191
fdde:ad00:beef:0:37ab:d7db:3252:f62a
Done
> panid
abcd
Done
> networkname
OpenThread
Done
> channel
11
Done
> state
leader
Done
> router table
| ID | RLOC16 | Next Hop | Path Cost | LQ In | LQ Out | Age | Extended MAC     |
+----+--------+----------+-----------+-------+--------+-----+------------------+
|  3 | 0x0c00 |        3 |         0 |     0 |      0 |  89 | 0000000000000000 |
| 30 | 0x7800 |        0 |         0 |     3 |      3 |   0 | b6d16f059a5ce29c |
| 52 | 0xd000 |        0 |         0 |     0 |      0 |  89 | 0000000000000000 |

Done

> ping fdde:ad00:beef:0:345c:52be:c8e4:a3eb
> 8 bytes from fdde:ad00:beef:0:345c:52be:c8e4:a3eb: icmp_seq=2 hlim=64 time=22ms

> ping fe80::b4d1:6f05:9a5c:e29c
> 8 bytes from fe80:0:0:0:b4d1:6f05:9a5c:e29c: icmp_seq=3 hlim=64 time=12ms

> ping ff03::1
> 8 bytes from fdde:ad00:beef:0:0:ff:fe00:7800: icmp_seq=4 hlim=64 time=9ms

> ping fdde:ad00:beef:0:0:ff:fe00:7800
> 8 bytes from fdde:ad00:beef:0:0:ff:fe00:7800: icmp_seq=5 hlim=64 time=8ms

We've checked it on two PCs with the same result.

Do you have any ideas what's wrong with it?

Kind regards,
Krzysztof

[Lukasz Duda]

Hello Krzysztof,

It looks that we have a bug in nrfutil's implementation of CoAP Server that we didn't spot due to different testing procedure (we first setup all nodes and then DFU Server).

In your logs we have spotted this line: 

2018-04-25 10:45:55,295 Sending response, type = ACK (request type = NON)

Obviously ACKs should not be sent in response to NON request.

As you see this function does not check the type of the request. In the correct behavior the trigger message should be sent instead of ACK from a DFU Server.

The solution is to modify _handle_trigger_request method to response with either NON/CON unicast trigger to the source node or with multicast trigger if the request is of NON type.

We are welcoming contribution to nrfutil, else we will try to fix it in 1st/2nd week of June.

[kpyush]

Lukasz Dudadid you guys fixed the bug you found in nrfutil's implementation ? we are facing exactly the same issue.  It is throwing same error even after we set up node first and DFU server after that.

[Lukasz Duda]

Hello kpyush,

Unfortunatelly not yet. We will try to fix it ASAP, i let you know.

[kpyush]

Hello Lukasz Duda ,

I captured the coap packets on thread network. It is strange that i haven't got any coap packet from dfu server(nrfutil). although i am being able to receive the coap packet of coap client (nrf52840-DK). Can you please point out the possible reason of this.

[Rafal Kuznia]

Hi Peeyush

I really apologise for such long delay on the matter.

The reason for nrfutil not responding to requests might be due to incompatibility with newer versions of pyspinel. Pyspinel 1.0.0a1 worked fine. A fix has been already made.

The bug with NON messages being responded to with ACK message has also been fixed.

Both of these fixes are now being tested and might be coming shortly.