nrf-util error while changing NCP network parameters

[kristofbo]

So we are using NCPTransport from nrf-util (nordicsemi/thread/tncp.py) to have CoAP connectivity over Thread NCP from Raspberry Pi to other Thread devices. We have a use case where we need to reconfigure NCP network parameters in order to reach device in another network. The problem is that we get errors while re-opening NCPTransport with new (or even the same) parameters.

NCP connected to RPi over Serial `/dev/ttyS0`.
NCP based on nRF5 SDK for Thread and Zigbee v2.0.0.

Python packages:
pyserial (3.4)
pyspinel (1.0.0a3)

Our test code in Python:

import logging

logging.basicConfig(
    format='%(asctime)s %(name)-6s %(message)s',
    datefmt='%H:%M:%S')

import time

class Thread:
    def __init__(self):
        self.log = logging.getLogger('Thread')
        self.log.setLevel(logging.INFO)

    def run(self):
        from nordicsemi.thread.tncp import NCPTransport

        self.log.info("Starting...")

        port = '/dev/ttyS0'
        stream_descriptor = 'u:' + port

        config = {NCPTransport.CFG_KEY_CHANNEL: 19,
                  NCPTransport.CFG_KEY_PANID: 0xbfb4,
                  NCPTransport.CFG_KEY_RESET: True}

        transport = NCPTransport(5683, stream_descriptor)
        transport.open()
        time.sleep(2)
        transport.close()
        time.sleep(2)


Thread().run()
Thread().run()

and logs:

17:14:39 Thread Starting...
17:14:40 nordicsemi.thread.tncp Attaching to the network
17:14:45 nordicsemi.thread.tncp Done
17:14:45 nordicsemi.thread.tncp NCP Thread IPv6 addresses:
17:14:45 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:fc10
17:14:45 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:fc00
17:14:45 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:0
17:14:45 nordicsemi.thread.tncp fe80::1837:7abe:9451:7b67
17:14:45 nordicsemi.thread.tncp fd4a:b255:f83d:0:2706:3899:e257:fb06
17:14:50 Thread Starting...
Exception in thread Thread-2:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/local/lib/python2.7/dist-packages/spinel/codec.py", line 965, in stream_rx
    self.rx_pkt = self.hdlc.collect()
  File "/usr/local/lib/python2.7/dist-packages/spinel/hdlc.py", line 80, in collect
    byte = self.stream.read()
  File "/usr/local/lib/python2.7/dist-packages/spinel/stream.py", line 69, in read
    pkt = self.serial.read(size)
  File "/usr/local/lib/python2.7/dist-packages/serial/serialposix.py", line 501, in read
    'device reports readiness to read but returned no data '
SerialException: device reports readiness to read but returned no data (device disconnected or multiple access on port?)

Traceback (most recent call last):
  File "ncp_forming.py", line 34, in <module>
    Thread().run()
  File "ncp_forming.py", line 27, in run
    transport.open()
  File "/tmp/nfs/factory_validation/app/src/nordicsemi/thread/tncp.py", line 224, in open
    raise Exception('Failed to reset NCP. Please flash connectivity firmware.')
Exception: Failed to reset NCP. Please flash connectivity firmware.

We tried to fix it by adding `close` implementation to class StreamSerial() in spinel/stream.py:

    def close(self):
        print("Closing serial")
        self.serial.close()

and now it works better, network is formed again, but still we get exception like below:

17:16:56 Thread Starting...
17:16:56 nordicsemi.thread.tncp Attaching to the network
17:17:01 nordicsemi.thread.tncp Done
17:17:01 nordicsemi.thread.tncp NCP Thread IPv6 addresses:
17:17:01 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:fc10
17:17:01 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:fc00
17:17:01 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:0
17:17:01 nordicsemi.thread.tncp fe80::1837:7abe:9451:7b67
17:17:01 nordicsemi.thread.tncp fd4a:b255:f83d:0:2706:3899:e257:fb06
Closing serial
17:17:05 Thread Starting...
Exception in thread Thread-2:
Traceback (most recent call last):
  File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
    self.run()
  File "/usr/lib/python2.7/threading.py", line 754, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/local/lib/python2.7/dist-packages/spinel/codec.py", line 965, in stream_rx
    self.rx_pkt = self.hdlc.collect()
  File "/usr/local/lib/python2.7/dist-packages/spinel/hdlc.py", line 80, in collect
    byte = self.stream.read()
  File "/usr/local/lib/python2.7/dist-packages/spinel/stream.py", line 69, in read
    pkt = self.serial.read(size)
  File "/usr/local/lib/python2.7/dist-packages/serial/serialposix.py", line 493, in read
    buf = os.read(self.fd, size - len(read))
TypeError: an integer is required

17:17:06 nordicsemi.thread.tncp Attaching to the network
17:17:11 nordicsemi.thread.tncp Done
17:17:11 nordicsemi.thread.tncp NCP Thread IPv6 addresses:
17:17:11 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:fc10
17:17:11 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:fc00
17:17:11 nordicsemi.thread.tncp fd4a:b255:f83d::ff:fe00:0
17:17:11 nordicsemi.thread.tncp fe80::1837:7abe:9451:7b67
17:17:11 nordicsemi.thread.tncp fd4a:b255:f83d:0:2706:3899:e257:fb06
Closing serial

Please advise if you have any idea how to fix this issue.

Thanks,
Krzysztof

[kristofbo]

I've just tried it on nRF52840 DK - the same result.

[Stian Røed Hafskjold]

Hi, sorry for the late reply but did you try the native USB port on the nRF52840 instead of the UART over SEGGER version of the firmware?

[AndreasF]

Hi Krzysztof.

I have contacted the Thread team asking for support about this issue, please be patient :-)

Best regards,

Andreas

[AndreasF]

Hi Krzysztof.

Still waiting for response on this issue.

In the meantime, are you able to reproduce this issue with our latest SDK, version 3.1.0?

Edit:

What are your use case for NCP Transport? Are you trying to do a DFU? Sending CoAP packets?

Are you familiar with the wpantund that creates regular network interface for Thread networks on posix systems?

Best regards,

Andreas

[kristofbo]

Hi,

I didn't check it on SDK, version 3.1.0 so far.

Our use case is to send CoAP messages from python application on linux to devices in Thread network. We are basing on CoAP communication layer used in python DFU server, because it already uses scenarios we need.

Regards,
Krzysztof

[AndreasF]

Hi again Krzysztof.

One of our developers have had a look at the issue and think he has found the root cause.

It appears that the cause of the issue is located in pyspinel.

The problem appears to be in hdlc.py stream.py and codec.py.

The problem is that stream_rx inside of codec.py runs in a separate thread.

When we close the transport, the file descriptor associated with the serial port is closed and set to None when we close the transport from the main thread.

This causes the stream_rx thread fail because it attempts to read from a closed file descriptor.

This is after the fix you have tried to make, which our developer agrees should be there.

I suggest that you can make a new issue on GitHub where you explain this issue if possible.

Best regards,

Andreas

[kristofbo]

Hi,

Thank you  for the information.

I've just created the issue: https://github.com/openthread/pyspinel/issues/61

Regards,
Krzysztof