Zephyr and OpenThread join support

[Louis]

While attempting to join a network formed by the OpenThread border router reference implementation and an external commissioner using the Android app, my zephyr end device (based on the lwm2m client sample) ends up failing an assertion:

assertion "awaited_property == AWAITED_PROPERTY_NONE" failed: file "WEST_TOPDIR/zephyr/modules/hal_nordic/nrf_802154/serialization/platform/nrf_802154_spinel_response_notifier.c", line 63, function: nrf_802154_spinel_response_notifier_lock_before_request

I'm not sure I'm doing this properly. CONFIG_OPENTHREAD_CUSTOM_PARAMETERS has to be set in order to be able to link the binary which I think is a little suspicious and not documented as far as I know:

CONFIG_OPENTHREAD_JOINER=y
CONFIG_OPENTHREAD_CUSTOM_PARAMETERS="OPENTHREAD_CONFIG_JOINER_ENABLE=1"
CONFIG_OPENTHREAD_JOINER_AUTOSTART=y
CONFIG_OPENTHREAD_JOINER_PSKD="J01NU5"
CONFIG_MBEDTLS_HEAP_SIZE=10240

[Carl Richard]

Hello, Louis!

Are you using Zephyr standalone or the nRF Connect SDK, based on Zephyr? In the latter we provide a OpenThread configuration guide and samples that should be more straightforward to setup with our devices. 

I will ask the developers about the issue you're seeing here.

Best regards,
Carl Richard

[Louis]

Thanks,

I'm using the nRF SDK. I tried to add join support to the cli sample. Configuring the application with OPENTHREAD_JOINER_AUTOSTART didin't do anything (no failed assertion but no join either). So I added a "join button" (project here) and ended up with the same failed assertion.

[Carl Richard]

Hi!

I thinking about logs from the code running on the network core of the nRF5340. You should have the "hci_rpmsg" sample running on it. Logging should be enabled by default in the sample, but for increased verbosity you can add:

CONFIG_LOG_DEFAULT_LEVEL=4
CONFIG_BT_DEBUG_LOG=y

Please notify me if anything is unclear!

Best regards,
Carl Richard

[Louis]

Hi Carl,

I think there's a misunderstanding. The issue is with the OpenThread stack. However, those were indeed the logs from the application core. Those from the network core (first tty) are empty. 

I tried :

CONFIG_LOG_DEFAULT_LEVEL=4

but it actually triggers a boot loop with the OpenThread CLI sample from nRF Connect SDK. 

[Carl Richard]

Hello again!

I was informed by the developers that the assertion you're seeing here likely is related to problems with the communication between the network and the application core. My instructions for logging earlier were wrong, as I was unaware that a different sample is running on the network core for 802154 applications. New instructions follows:
1. Create a new directory "child_image" in the project folder.
2. Create a file in the directory with the name "802154_rpmsg.conf".
3. Add the following configurations to the file:

CONFIG_SERIAL=y
CONFIG_UART_CONSOLE=y
CONFIG_LOG=y
CONFIG_NRF_802154_SER_LOG=y

4. Rebuild the project as "pristine" and flash. If you are using Segger Embedded Studio reopen the project with a "Clean Build Folder" before building and flashing.

This should result in verbose logging from the network core. Please notify me if anything is unclear! And by the way; which version of the nRF Connect SDK are you using?

Best regards,
Carl Richard

[Louis]

Hi Carl,

Here's the output from the network core but nothing else shows up as I trigger a join:

*** Booting Zephyr OS build v2.4.99-ncs1-1818-g54dea0b2b530  ***
Received spinel frame
        data: 0x80 0x03 0x9f 0x78
        data_address: 0x20072410
Sending spinel frame
        data: 0x80 0x06 0x9f 0x78 0x09 0x00 0x00 0x00
        data_address: 0x21005358
Received spinel frame
        data: 0x80 0x03 0x81 0x78
        data_address: 0x20072410
Sending spinel frame
        data: 0x80 0x06 0x81 0x78 0x01
        data_address: 0x21005358
Received spinel frame
        data: 0x80 0x03 0x8e 0x78 0x4d 0x77 0xe9 0x8f 0xb0 0xd1 0x64 0x7e
        data_address: 0x20072410
Sending spinel frame
        data: 0x80 0x06 0x00 0x00
        data_address: 0x21005358
Received spinel frame
        data: 0x80 0x03 0x8d 0x78 0xfe 0xff
        data_address: 0x20072410
Sending spinel frame
        data: 0x80 0x06 0x00 0x00
        data_address: 0x21005358
Received spinel frame
        data: 0x80 0x03 0x8a 0x78 0x00
        data_address: 0x20072410
Sending spinel frame
        data: 0x80 0x06 0x00 0x00
        data_address: 0x21005358
Received spinel frame
        data: 0x80 0x03 0x8a 0x78 0x01
        data_address: 0x20072410
Sending spinel frame
        data: 0x80 0x06 0x00 0x00
        data_address: 0x21005358

[Carl Richard]

Understood. Are you able to test whether on-mesh Thread commisioning also triggers the issue? To make it easier for the developers to look into this please provide the following details:
- Your NCS version
- Which sample code you are testing
- Your project configuration (.conf files and build\zephyr\include\generated\autoconf.h).
- How you're building the project (SES or command line?)
- nRF5340DK version

Best regards,
Carl Richard

[Louis]

Hi Carl,

I confirm that nothing from the zephyr base was changed. Here's the output of the log: 

-- west build: generating a build system
Including boilerplate (Zephyr base): /home/theia/zephyr/cmake/app/boilerplate.cmake
-- Application: /home/project/cli
-- Zephyr version: 2.5.99 (/home/theia/zephyr)
-- Found Python3: /usr/bin/python3.6 (found suitable exact version "3.6.9") found components: Interpreter 
-- Found west (found suitable version "0.10.1", minimum required is "0.7.1")
-- Board: nrf5340dk_nrf5340_cpuapp
-- Cache files will be written to: /home/theia/.cache/zephyr
-- Found toolchain: gnuarmemb (/opt/gcc-arm-none-eabi/gcc-arm-none-eabi-10-2020-q4-major)
-- Found BOARD.dts: /home/theia/zephyr/boards/arm/nrf5340dk_nrf5340/nrf5340dk_nrf5340_cpuapp.dts
-- Generated zephyr.dts: /home/project/cli/build/zephyr/zephyr.dts
-- Generated devicetree_unfixed.h: /home/project/cli/build/zephyr/include/generated/devicetree_unfixed.h
-- Generated device_extern.h: /home/project/cli/build/zephyr/include/generated/device_extern.h

warning: SHELL_STACK_SIZE (defined at subsys/shell/Kconfig:28) was assigned the value '2048' but got
the value ''. Check these unsatisfied dependencies: SHELL (=n). See
http://docs.zephyrproject.org/latest/reference/kconfig/CONFIG_SHELL_STACK_SIZE.html and/or look up
SHELL_STACK_SIZE in the menuconfig/guiconfig interface. The Application Development Primer, Setting
Configuration Values, and Kconfig - Tips and Best Practices sections of the manual might be helpful
too.


warning: SHELL_CMD_BUFF_SIZE (defined at subsys/shell/Kconfig:44) was assigned the value '416' but
got the value ''. Check these unsatisfied dependencies: SHELL (=n). See
http://docs.zephyrproject.org/latest/reference/kconfig/CONFIG_SHELL_CMD_BUFF_SIZE.html and/or look
up SHELL_CMD_BUFF_SIZE in the menuconfig/guiconfig interface. The Application Development Primer,
Setting Configuration Values, and Kconfig - Tips and Best Practices sections of the manual might be
helpful too.


warning: SHELL_ARGC_MAX (defined at subsys/shell/Kconfig:70) was Parsing /home/project/cli/Kconfig
Loaded configuration '/home/theia/zephyr/boards/arm/nrf5340dk_nrf5340/nrf5340dk_nrf5340_cpuapp_defconfig'
Merged configuration '/home/project/cli/prj_nrf5340dk_nrf5340_cpuapp.conf'
Merged configuration '/home/theia/zephyr/../nrf/samples/openthread/common/overlay-ot-defaults.conf'
Configuration saved to '/home/project/cli/build/zephyr/.config'
Kconfig header saved to '/home/project/cli/build/zephyr/include/generated/autoconf.h'
assigned the value '26' but got the
value ''. Check these unsatisfied dependencies: SHELL (=n). See
http://docs.zephyrproject.org/latest/reference/kconfig/CONFIG_SHELL_ARGC_MAX.html and/or look up
SHELL_ARGC_MAX in the menuconfig/guiconfig interface. The Application Development Primer, Setting
Configuration Values, and Kconfig - Tips and Best Practices sections of the manual might be helpful
too.

-- The C compiler identification is GNU 10.2.1
-- The CXX compiler identification is GNU 10.2.1
-- The ASM compiler identification is GNU
-- Found assembler: /opt/gcc-arm-none-eabi/gcc-arm-none-eabi-10-2020-q4-major/bin/arm-none-eabi-gcc
Adding '802154_rpmsg' firmware as child image since CONFIG_NRF_802154_SER_HOST is set to y

=== child image 802154_rpmsg - CPUNET begin ===
Including boilerplate (Zephyr base): /home/theia/zephyr/cmake/app/boilerplate.cmake
-- Application: /home/theia/zephyr/samples/boards/nrf/ieee802154/802154_rpmsg
-- Zephyr version: 2.5.99 (/home/theia/zephyr)
-- Found Python3: /usr/bin/python3.6 (found suitable exact version "3.6.9") found components: Interpreter 
-- Found west (found suitable version "0.10.1", minimum required is "0.7.1")
-- Board: nrf5340dk_nrf5340_cpunet
-- Cache files will be written to: /home/theia/.cache/zephyr
-- Found toolchain: gnuarmemb (/opt/gcc-arm-none-eabi/gcc-arm-none-eabi-10-2020-q4-major)
-- Found BOARD.dts: /home/theia/zephyr/boards/arm/nrf5340dk_nrf5340/nrf5340dk_nrf5340_cpunet.dts
-- Generated zephyr.dts: /home/project/cli/build/802154_rpmsg/zephyr/zephyr.dts
-- Generated devicetree_unfixed.h: /home/project/cli/build/802154_rpmsg/zephyr/include/generated/devicetree_unfixed.h
-- Generated device_extern.h: /home/project/cli/build/802154_rpmsg/zephyr/include/generated/device_extern.h
Parsing /home/theia/zephyr/Kconfig
Loaded configuration '/home/theia/zephyr/boards/arm/nrf5340dk_nrf5340/nrf5340dk_nrf5340_cpunet_defconfig'
Merged configuration '/home/theia/zephyr/samples/boards/nrf/ieee802154/802154_rpmsg/prj.conf'
Merged configuration '/home/theia/nrf/subsys/partition_manager/partition_manager_enabled.conf'
Merged configuration '/home/project/cli/child_image/802154_rpmsg.conf'
Configuration saved to '/home/project/cli/build/802154_rpmsg/zephyr/.config'
Kconfig header saved to '/home/project/cli/build/802154_rpmsg/zephyr/include/generated/autoconf.h'
-- The C compiler identification is GNU 10.2.1
-- The CXX compiler identification is GNU 10.2.1
-- The ASM compiler identification is GNU
-- Found assembler: /opt/gcc-arm-none-eabi/gcc-arm-none-eabi-10-2020-q4-major/bin/arm-none-eabi-gcc
-- Build type:  
-- Host:    Linux/x86_64
-- Target:  Generic/arm
-- Machine: cortexm
-- Looking for include file stdatomic.h
-- Looking for include file stdatomic.h - found
-- Host:    Linux/x86_64
-- Target:  Generic/arm
-- Machine: cortexm
-- C_FLAGS :  -Wall -Wextra
-- Looking for include file fcntl.h
-- Looking for include file fcntl.h - found
-- Configuring done
-- Generating done
-- Build files have been written to: /home/project/cli/build/802154_rpmsg
=== child image 802154_rpmsg - CPUNET end ===

-- Build type:  
-- Host:    Linux/x86_64
-- Target:  Generic/arm
-- Machine: cortexm
-- Looking for include file stdatomic.h
-- Looking for include file stdatomic.h - found
-- Host:    Linux/x86_64
-- Target:  Generic/arm
-- Machine: cortexm
-- C_FLAGS :  -Wall -Wextra
-- Looking for include file fcntl.h
-- Looking for include file fcntl.h - found
-- Check if the system is big endian
-- Searching 16 bit integer
-- Looking for sys/types.h
-- Looking for sys/types.h - found
-- Looking for stdint.h
-- Looking for stdint.h - found
-- Looking for stddef.h
-- Looking for stddef.h - found
-- Check size of unsigned short
-- Check size of unsigned short - done
-- Searching 16 bit integer - Using unsigned short
-- Check if the system is big endian - little endian
-- CMake build type: Debug
-- Version: gfd27fc3a7
CMake Warning at /home/theia/zephyr/CMakeLists.txt:1434 (message):
  

        The CMake build type was set to 'Debug', but the optimization flag was set to '-Os'.
        This may be intentional and the warning can be turned off by setting the CMake variable 'NO_BUILD_TYPE_WARNING'


-- Configuring done
-- Generating done
-- Build files have been written to: /home/project/cli/build
-- west build: building application
[3/521] Preparing syscall dependency handling

[13/521] Performing build step for '802154_rpmsg_subimage'
[1/241] Preparing syscall dependency handling

[232/241] Linking C executable zephyr/zephyr_prebuilt.elf

[239/241] Linking C executable zephyr/zephyr.elf
Memory region         Used Size  Region Size  %age Used
           FLASH:       84348 B       256 KB     32.18%
            SRAM:       28416 B        64 KB     43.36%
        IDT_LIST:          0 GB         2 KB      0.00%

[241/241] Generating zephyr/merged_CPUNET.hex
[16/521] cd /home/project/cli/build/modules/openthread/build && /home/theia/.local/lib/python3.6/site-packages/cmake/data/bin/cmake -DLIST="OPENTHREAD_CONFIG_ASSERT_ENABLE=1;OPENTHREAD_CONFIG_BACKBONE_ROUTER_DUA_NDPROXYING_ENABLE=0;OPENTHREAD_CONFIG_BACKBONE_ROUTER_MULTICAST_ROUTING_ENABLE=0;OPENTHREAD_CONFIG_BORDER_AGENT_ENABLE=1;OPENTHREAD_CONFIG_BORDER_ROUTER_ENABLE=1;OPENTHREAD_CONFIG_ENABLE_BUILTIN_MBEDTLS=0;OPENTHREAD_CONFIG_ENABLE_BUILTIN_MBEDTLS_MANAGEMENT=0;OPENTHREAD_CONFIG_CHILD_SUPERVISION_ENABLE=1;OPENTHREAD_CONFIG_COAP_API_ENABLE=1;OPENTHREAD_CONFIG_COAP_SECURE_API_ENABLE=1;OPENTHREAD_CONFIG_COMMISSIONER_ENABLE=1;OPENTHREAD_CONFIG_DHCP6_CLIENT_ENABLE=1;OPENTHREAD_CONFIG_DHCP6_SERVER_ENABLE=1;OPENTHREAD_CONFIG_DIAG_ENABLE=1;OPENTHREAD_CONFIG_DNS_CLIENT_ENABLE=1;OPENTHREAD_CONFIG_ECDSA_ENABLE=1;OPENTHREAD_CONFIG_HEAP_EXTERNAL_ENABLE=1;OPENTHREAD_CONFIG_IP6_FRAGMENTATION_ENABLE=1;OPENTHREAD_CONFIG_JAM_DETECTION_ENABLE=1;OPENTHREAD_CONFIG_JOINER_ENABLE=1;OPENTHREAD_CONFIG_LINK_RAW_ENABLE=1;OPENTHREAD_CONFIG_MAC_FILTER_ENABLE=1;OPENTHREAD_CONFIG_TMF_NETWORK_DIAG_MTD_ENABLE=1;OPENTHREAD_CONFIG_TMF_NETDATA_SERVICE_ENABLE=1;OPENTHREAD_CONFIG_IP6_SLAAC_ENABLE=1;OPENTHREAD_CONFIG_SNTP_CLIENT_ENABLE=1;OPENTHREAD_CONFIG_UDP_FORWARD_ENABLE=1;OPENTHREAD_SPINEL_CONFIG_RCP_RESTORATION_MAX_COUNT=0;PACKAGE_NAME="OPENTHREAD";PACKAGE_VERSION="gfd27fc3a7";OPENTHREAD_CONFIG_THREAD_VERSION=OT_THREAD_VERSION_1_1;OPENTHREAD_CONFIG_NCP_UART_ENABLE=1;KERNEL;__ZEPHYR__=1;_FORTIFY_SOURCE=2;BUILD_VERSION=v2.4.99-ncs1-1818-g54dea0b2b530;__LINUX_ERRNO_EXTENSIONS__;USE_PARTITION_MANAGER=1;__PROGRAM_START;NRF5340_XXAA_APPLICATION;MBEDTLS_CONFIG_FILE="nrf-config.h"" -P /home/theia/modules/lib/openthread/etc/cmake/print.cmake
OPENTHREAD_CONFIG_ASSERT_ENABLE=1
OPENTHREAD_CONFIG_BACKBONE_ROUTER_DUA_NDPROXYING_ENABLE=0
OPENTHREAD_CONFIG_BACKBONE_ROUTER_MULTICAST_ROUTING_ENABLE=0
OPENTHREAD_CONFIG_BORDER_AGENT_ENABLE=1
OPENTHREAD_CONFIG_BORDER_ROUTER_ENABLE=1
OPENTHREAD_CONFIG_ENABLE_BUILTIN_MBEDTLS=0
OPENTHREAD_CONFIG_ENABLE_BUILTIN_MBEDTLS_MANAGEMENT=0
OPENTHREAD_CONFIG_CHILD_SUPERVISION_ENABLE=1
OPENTHREAD_CONFIG_COAP_API_ENABLE=1
OPENTHREAD_CONFIG_COAP_SECURE_API_ENABLE=1
OPENTHREAD_CONFIG_COMMISSIONER_ENABLE=1
OPENTHREAD_CONFIG_DHCP6_CLIENT_ENABLE=1
OPENTHREAD_CONFIG_DHCP6_SERVER_ENABLE=1
OPENTHREAD_CONFIG_DIAG_ENABLE=1
OPENTHREAD_CONFIG_DNS_CLIENT_ENABLE=1
OPENTHREAD_CONFIG_ECDSA_ENABLE=1
OPENTHREAD_CONFIG_HEAP_EXTERNAL_ENABLE=1
OPENTHREAD_CONFIG_IP6_FRAGMENTATION_ENABLE=1
OPENTHREAD_CONFIG_JAM_DETECTION_ENABLE=1
OPENTHREAD_CONFIG_JOINER_ENABLE=1
OPENTHREAD_CONFIG_LINK_RAW_ENABLE=1
OPENTHREAD_CONFIG_MAC_FILTER_ENABLE=1
OPENTHREAD_CONFIG_TMF_NETWORK_DIAG_MTD_ENABLE=1
OPENTHREAD_CONFIG_TMF_NETDATA_SERVICE_ENABLE=1
OPENTHREAD_CONFIG_IP6_SLAAC_ENABLE=1
OPENTHREAD_CONFIG_SNTP_CLIENT_ENABLE=1
OPENTHREAD_CONFIG_UDP_FORWARD_ENABLE=1
OPENTHREAD_SPINEL_CONFIG_RCP_RESTORATION_MAX_COUNT=0
PACKAGE_NAME=OPENTHREAD
PACKAGE_VERSION=gfd27fc3a7
OPENTHREAD_CONFIG_THREAD_VERSION=OT_THREAD_VERSION_1_1
OPENTHREAD_CONFIG_NCP_UART_ENABLE=1
KERNEL
__ZEPHYR__=1
_FORTIFY_SOURCE=2
BUILD_VERSION=v2.4.99-ncs1-1818-g54dea0b2b530
__LINUX_ERRNO_EXTENSIONS__
USE_PARTITION_MANAGER=1
__PROGRAM_START
NRF5340_XXAA_APPLICATION
MBEDTLS_CONFIG_FILE=nrf-config.h
[512/521] Linking CXX executable zephyr/zephyr_prebuilt.elf

[519/521] Linking CXX executable zephyr/zephyr.elf
Memory region         Used Size  Region Size  %age Used
           FLASH:      333684 B      1016 KB     32.07%
            SRAM:       87128 B       512 KB     16.62%
        IDT_LIST:          0 GB         2 KB      0.00%

[521/521] Generating zephyr/merged_domains.hex

[Louis]

Unfortunately still the same result with the latest version. Note that nrf is at the same level as $ZEPHYR_BASE on my install, not under it which seems consistent with what I see here.

[Carl Richard]

That's unfortunate. Did you try with the pull request I mentioned as well? 

ZEPHYR_BASE is supposed to point to <ncs_install_folder>/zephyr. The nrf folder is located at <ncs_install_folder>/nrf. I believe is used the wrong path in my earlier instructions. Apologies for that!

Best regards,
Carl Richard

[Louis]

No problem. Yes, I pulled everything uptream including <ncs_install_folder>/nrf.

[Carl Richard]

Ok! Thanks.

Could you get me the current commit hash of nrfxlib? Enter <ncs_install_folder>/nrfxlib and call

git rev-parse HEAD

Best regards,
Carl Richard