OpenThread not work after upgrade to latest version

[ghlualven]

Describe the bug
Upgrade to the latest code Zephyr 2.3.0-rc1 (Zephyr OS build v2.3.0-rc1-26-g4980a13fc4f7), the firmware initial works. But after execute "ot scan" command, no any output and the board bricked. Re-power is not working, the board must be re-flashed.

The same program is working at: Zephyr OS build zephyr-v2.2.0-881-gecb85a7db1f1.

[rlubos]

@ghlualven I think we need more information here. I've just tried the ot scan command in the echo_server sample, running on nRF52840, and it works just fine. I've used the recent rc tag (Zephyr OS build v2.3.0-rc1).

What board do you use? Can you reporoduce the issue on any of the existing Zephyr samples? Did you run west update after switching to the rc1? There were changes on both sides, Zephyr and OpenThread.

[ghlualven]

@rlubos I tried again today, and find the echo_server project works fine, but lwm2m_client doesn't.
I copied the overlay-ot.conf file from echo_server to lwm2m_client project, the build and flash both successful, but thread network can not work the same:

1. ot scan command will no response, and will not get back "Done" message to timeout;
2. No "Beacon" packet send out from radio.
3. Always show busy after this command executed.

This is the output from echo_server sample:

 *** Booting Zephyr OS build v2.3.0-rc1-26-g4980a13fc4f7  ***
[00:00:00.250,793] <inf> ieee802154_nrf5: nRF5 802154 radio initialized
[00:00:00.264,160] <inf> fs_nvs: 8 Sectors of 4096 bytes
[00:00:00.264,160] <inf> fs_nvs: alloc wra: 0, e10
[00:00:00.264,190] <inf> fs_nvs: data wra: 0, 3ac
[00:00:00.269,012] <inf> net_l2_openthread: State changed! Flags: 0x011fd309 Current role: 0
[00:00:00.270,385] <inf> net_l2_openthread: OpenThread version: OPENTHREAD/ga83d18cf; NONE; May 14 2020 08:08:14
[00:00:00.270,416] <inf> net_l2_openthread: Network name: kirale-06B4
[00:00:00.270,416] <inf> net_l2_openthread: State changed! Flags: 0x00000004 Current role: 1
[00:00:00.270,507] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: 1
[00:00:00.270,599] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: 1
[00:00:00.270,721] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: 1
[00:00:00.270,843] <inf> net_l2_openthread: State changed! Flags: 0x00000010 Current role: 1
[00:00:00.270,874] <inf> net_l2_openthread: State changed! Flags: 0x00000020 Current role: 1
[00:00:00.282,531] <inf> net_config: Initializing network
[00:00:00.282,653] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: 1
[00:00:00.298,309] <inf> net_l2_openthread: State changed! Flags: 0x000010e4 Current role: 3
[00:00:00.319,793] <inf> net_l2_openthread: State changed! Flags: 0x00000200 Current role: 3
[00:00:00.319,824] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: 3
[00:00:03.283,081] <inf> net_echo_server_sample: Run echo server
[00:00:03.283,111] <inf> net_echo_server_sample: Network connected
[00:00:03.283,142] <inf> net_echo_server_sample: Starting...
[00:00:03.283,264] <inf> net_echo_server_sample: Waiting for UDP packets on port 4242 (IPv6)...
uart:~$ ot scan
| J | Network Name     | Extended PAN     | PAN  | MAC Address      | Ch | dBm | LQI |
+---+------------------+------------------+------+------------------+----+-----+-----+
| 0 | OpenThread       | dead00beef00cafe | abcd | 2e6c35c5155ae11a | 11 | -55 | 160 |
| 1 | kirale-06B4      | 0948130241ac0b32 | 06b4 | eb003594d71e6f1a | 11 | -58 | 140 |
Done
uart:~$ log halt
uart:~$ ot scan
| J | Network Name     | Extended PAN     | PAN  | MAC Address      | Ch | dBm | LQI |
+---+------------------+------------------+------+------------------+----+-----+-----+
| 0 | OpenThread       | dead00beef00cafe | abcd | 2e6c35c5155ae11a | 11 | -54 | 160 |
| 1 | kirale-06B4      | 0948130241ac0b32 | 06b4 | eb003594d71e6f1a | 11 | -58 | 140 |
Done
uart:~$ 

This is the output from lwm2m_client sample:

*** Booting Zephyr OS build v2.3.0-rc1-26-g4980a13fc4f7  ***
[00:00:00.247,528] <inf> ieee802154_nrf5: nRF5 802154 radio initialized
[00:00:00.260,681] <inf> fs_nvs: 8 Sectors of 4096 bytes
[00:00:00.260,681] <inf> fs_nvs: alloc wra: 0, f30
[00:00:00.260,681] <inf> fs_nvs: data wra: 0, 174
[00:00:00.262,054] <inf> net_l2_openthread: State changed! Flags: 0x011fd319 Current role: 0
[00:00:00.262,786] <inf> net_l2_openthread: OpenThread version: OPENTHREAD/ga83d18cf; NONE; May 14 2020 08:49:57
[00:00:00.262,786] <inf> net_l2_openthread: Network name: ot_zephyr
[00:00:00.262,817] <inf> net_l2_openthread: State changed! Flags: 0x00000004 Current role: 1
[00:00:00.262,908] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: 1
[00:00:00.263,000] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: 1
[00:00:00.263,122] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Current role: 1
[00:00:00.263,244] <inf> net_l2_openthread: State changed! Flags: 0x00000010 Current role: 1
[00:00:00.263,275] <inf> net_l2_openthread: State changed! Flags: 0x00000020 Current role: 1
[00:00:00.272,216] <dbg> net_lwm2m_engine.lwm2m_engine_init: LWM2M engine socket receive thread started
[00:00:00.272,277] <dbg> net_lwm2m_obj_security.security_create: Create LWM2M security instance: 0
[00:00:00.272,308] <dbg> net_lwm2m_obj_server.server_create: Create LWM2M server instance: 0
[00:00:00.272,399] <dbg> net_lwm2m_obj_device.device_create: Create LWM2M device instance: 0
[00:00:00.272,430] <dbg> net_lwm2m_obj_conn_mon.connmon_create: Create LWM2M connectivity monitoring instance: 0
[00:00:00.272,460] <dbg> net_lwm2m_obj_firmware.firmware_create: Create LWM2M firmware instance: 0
[00:00:00.272,460] <dbg> net_lwm2m_obj_location.location_create: Create Location instance: 0
[00:00:00.272,491] <inf> net_config: Initializing network
[00:00:00.272,644] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Current role: 1
[00:00:02.267,364] <inf> net_l2_openthread: State changed! Flags: 0x00000040 Current role: 1
[00:00:03.272,735] <inf> net_lwm2m_client_app: Run LWM2M client
[00:00:03.272,827] <dbg> net_lwm2m_engine.lwm2m_engine_set: path:0/0/2, value:0x20011a8f, len:1
[00:00:03.273,254] <dbg> net_lwm2m_engine.lwm2m_engine_create_obj_inst: path:3303/0
[00:00:03.273,315] <dbg> net_ipso_temp_sensor.temp_sensor_create: Create IPSO Temperature Sensor instance: 0
[00:00:03.273,345] <dbg> net_lwm2m_engine.lwm2m_engine_create_obj_inst: path:3311/0
[00:00:03.273,376] <dbg> net_ipso_light_control.light_control_create: Create IPSO Light Control instance: 0
[00:00:03.273,437] <dbg> net_lwm2m_engine.lwm2m_engine_create_obj_inst: path:3340/0
[00:00:03.273,498] <dbg> net_ipso_timer.timer_create: Create IPSO Timer instance: 0
[00:00:03.273,620] <inf> net_lwm2m_rd_client: Start LWM2M Client: nrf52840dk_nrf52840
[00:00:04.272,705] <dbg> net_lwm2m_engine.lwm2m_engine_get: path:0/0/1, buf:0x20011417, buflen:1
[00:00:04.272,766] <dbg> net_lwm2m_engine.lwm2m_engine_get: path:1/0/1, buf:0x200010a0, buflen:4
[00:00:04.272,796] <inf> net_lwm2m_rd_client: RD Client started with endpoint 'nrf52840dk_nrf52840' with client lifetime 30
[00:00:04.272,827] <dbg> net_lwm2m_engine.lwm2m_parse_peerinfo: Parse url: <log_strdup alloc failed>
[00:00:04.275,451] <dbg> net_lwm2m_rd_client.sm_send_registration: registration sent [<log_strdup alloc failed>]
[00:00:04.927,581] <inf> net_l2_openthread: State changed! Flags: 0x000012a5 Current role: 4
[00:00:06.620,483] <inf> net_lwm2m_engine: Resending message: 0x20007d70
uart:~$ ot scan
| J | Network Name     | Extended PAN     | PAN  | MAC Address      | Ch | dBm | LQI |
+---+------------------+------------------+------+------------------+----+-----+-----+
[00:00:11.308,807] <inf> net_lwm2m_engine: Resending message: 0x20007d70
[00:00:20.688,140] <inf> net_lwm2m_engine: Resending message: 0x20007d70
uart:~$ log halt
uart:~$ ot scan
| J | Network Name     | Extended PAN     | PAN  | MAC Address      | Ch | dBm | LQI |
+---+------------------+------------------+------+------------------+----+-----+-----+
Error 5: Busy
uart:~$ 

I use board: nrf52840dk_nrf52840. The zephyproject folder was "west update" already. One thing that different with my yesterdays report is the "ot scan" will not brick the board.

zephyrproject % west update
=== updating cmsis (modules/hal/cmsis):
HEAD is now at 542b229 DSP: Integrate CMSIS-DSP 1.8.0 (CMSIS 5.7.0)
=== updating hal_atmel (modules/hal/atmel):
HEAD is now at 1fe96f0 samv71: patch: Fix GMAC priority queue register offsets
=== updating hal_altera (modules/hal/altera):
HEAD is now at 23c1c1d hal_altera: Conditionally include the Altera HAL
=== updating canopennode (modules/lib/canopennode):
HEAD is now at 5c6b056 stack: remove all GNU GPL licensed platform drivers
=== updating ci-tools (tools/ci-tools):
HEAD is now at da9a2df labels: change test suite label
=== updating civetweb (modules/lib/civetweb):
HEAD is now at 99129c5e Merge pull request #778 from antmicro/zephyr-filtering
=== updating esp-idf (modules/hal/esp-idf):
HEAD is now at 6835bfc74 module: add zephyr integration
=== updating fatfs (modules/fs/fatfs):
HEAD is now at 9ee6b9b fs: Expose _USE_LFN, _MAX_LFN, and _CODE_PAGE as kconfig options.
=== updating hal_cypress (modules/hal/cypress):
HEAD is now at a12d928 zephyr: move kconfig to the zephyr tree
=== updating hal_infineon (modules/hal/infineon):
HEAD is now at f1fa824 hal: infineon: initial commit of XMCLib
=== updating hal_nordic (modules/hal/nordic):
HEAD is now at e1168a2 nrfx_spim: Fix error log message.
=== updating hal_openisa (modules/hal/openisa):
HEAD is now at 3b54187 hal: openisa: pass MIC status from CAUv3 on stack
=== updating hal_microchip (modules/hal/microchip):
HEAD is now at aad89bf modules: Fix MEC1501 OOB RX/TX transfer length masks
=== updating hal_silabs (modules/hal/silabs):
HEAD is now at 78da967 hal_silabs: patch: rename ramfunc section to match Zephyr's
=== updating hal_st (modules/hal/st):
HEAD is now at 5b3ec3e hal_st: CMakelists: Update coding style to main repo
=== updating hal_stm32 (modules/hal/stm32):
HEAD is now at d1bc80d hal_stm32: rename HAS_STLIB in HAS_STM32LIB
=== updating hal_ti (modules/hal/ti):
HEAD is now at c398cc7 cc13x2_cc26x2: drivers: fix build warnings in PowerCC26X2.c
=== updating libmetal (modules/hal/libmetal):
HEAD is now at 3c3c9ec lib: update libmetal to release v2020.04.0
=== updating lvgl (modules/lib/gui/lvgl):
HEAD is now at 74fc2e75 Merge lvgl v6.1.1 into zephyr branch
=== updating mbedtls (modules/crypto/mbedtls):
HEAD is now at 8211541 config-tls-generic: Add CTR cipher mode
=== updating mcuboot (bootloader/mcuboot):
M	boot/cypress/libs/core-lib
M	boot/cypress/libs/cy-mbedtls-acceleration
M	boot/cypress/libs/psoc6hal
M	boot/cypress/libs/retarget-io
HEAD is now at 5657d00 mergeup: merge up to upstream 82c5f7c
=== updating mcumgr (modules/lib/mcumgr):
HEAD is now at ac6cc4f snapshot: Update mcumgr to commit 9f6555ad from the upstream
=== updating net-tools (tools/net-tools):
HEAD is now at 1c4fdba docker: Add dante SOCKS 5 proxy
=== updating hal_nxp (modules/hal/nxp):
HEAD is now at 80a337d mcux: build LPC Entropy drivers
=== updating open-amp (modules/lib/open-amp):
HEAD is now at 724f7e2 lib: update open-amp lib to release v2020.04.0
=== updating loramac-node (modules/lib/loramac-node):
HEAD is now at 29e516ec radio: sx1276: allow overriding Buffer reand/write functions
=== updating openthread (modules/lib/openthread):
HEAD is now at a83d18cf cmake: Make sure libc is linked after OT libs
=== updating segger (modules/debug/segger):
HEAD is now at 6fcf616 ext: segger: update to SystemView v2.52h
=== updating tinycbor (modules/lib/tinycbor):
HEAD is now at 40daca9 zephyr: Remove TINYCBOR from interface libraries
=== updating tinycrypt (modules/crypto/tinycrypt):
HEAD is now at 3e9a49d cmake: Fix conditional in root CMakeLists.txt
=== updating littlefs (modules/fs/littlefs):
HEAD is now at 0aefdda Merge tag 'v2.2.0' into zephyr
=== updating mipi-sys-t (modules/debug/mipi-sys-t):
HEAD is now at 957d46b Delete initialization related code from mipi-sys-t tree
=== updating nrf_hw_models (modules/bsim_hw_models/nrf_hw_models):
HEAD is now at fec6970 Convert into a west module
=== updating hal_xtensa (modules/hal/xtensa):
HEAD is now at e7a57d0 hal: Add README for information on updating HAL versions.
=== updating edtt (tools/edtt):
HEAD is now at c39888f Update unsupported commands test to handle command status response
=== updating trusted-firmware-m (modules/tee/tfm):
HEAD is now at 7de2daa zephyr: cmake: TF-M libraries to be used by the ns-app
zephyrproject % 

[ghlualven]

build command:
west build -b nrf52840dk_nrf52840 -d build_nrf52840dk_nrf52840_ot -- -DCONF_FILE="prj.conf overlay-ot.conf"

overlay-ot.conf

CONFIG_NEWLIB_LIBC=y
CONFIG_CPLUSPLUS=y

CONFIG_BT=n

# Disable TCP and IPv4 (TCP disabled to avoid heavy traffic)
CONFIG_NET_TCP=n
CONFIG_NET_IPV4=n

CONFIG_NET_IPV6_NBR_CACHE=n
CONFIG_NET_IPV6_MLD=n
CONFIG_NET_CONFIG_NEED_IPV6=y
CONFIG_NET_CONFIG_NEED_IPV4=n
CONFIG_NET_CONFIG_MY_IPV4_ADDR=""
CONFIG_NET_CONFIG_PEER_IPV4_ADDR=""

CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048
CONFIG_NET_TX_STACK_SIZE=2048
CONFIG_NET_RX_STACK_SIZE=5120
CONFIG_SHELL_STACK_SIZE=3072

CONFIG_NET_L2_OPENTHREAD=y
CONFIG_OPENTHREAD_SLAAC=y

CONFIG_OPENTHREAD_DEBUG=y
CONFIG_OPENTHREAD_L2_DEBUG=y
CONFIG_OPENTHREAD_L2_LOG_LEVEL_INF=y

CONFIG_OPENTHREAD_CHANNEL=26

CONFIG_NET_CONFIG_MY_IPV6_ADDR="fdde:ad00:beef::2"
CONFIG_NET_CONFIG_PEER_IPV6_ADDR="fdde:ad00:beef::1"

# Thread by default registers quite a lot addresses.
CONFIG_NET_IF_UNICAST_IPV6_ADDR_COUNT=6
CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT=8

# Other OpenThread dependencies
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_MAP=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y
CONFIG_NVS=y
CONFIG_SETTINGS=y

CONFIG_REBOOT=y

# mbedTLS tweaks
CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=768

# A sample configuration to enable Thread Commissioner, uncomment if needed
#CONFIG_OPENTHREAD_JOINER=y
#CONFIG_OPENTHREAD_JOINER_AUTOSTART=y
#CONFIG_OPENTHREAD_COMMISSIONER=y
#CONFIG_MBEDTLS_HEAP_SIZE=8192

prj.conf

CONFIG_NETWORKING=y
CONFIG_LOG=y
CONFIG_LWM2M_LOG_LEVEL_DBG=y
CONFIG_TEST_RANDOM_GENERATOR=y
CONFIG_NET_IPV6=y
CONFIG_NET_IF_UNICAST_IPV6_ADDR_COUNT=3
CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT=2
CONFIG_NET_IPV4=y
CONFIG_NET_DHCPV4=n
CONFIG_NET_IF_UNICAST_IPV4_ADDR_COUNT=3
CONFIG_NET_IF_MCAST_IPV4_ADDR_COUNT=2
CONFIG_PRINTK=y
CONFIG_NET_PKT_RX_COUNT=10
CONFIG_NET_PKT_TX_COUNT=10
CONFIG_NET_BUF_RX_COUNT=10
CONFIG_NET_BUF_TX_COUNT=10
CONFIG_NET_MAX_CONTEXTS=5

CONFIG_NET_LOG=y
CONFIG_NET_SHELL=y

CONFIG_NET_CONFIG_NEED_IPV6=y
CONFIG_NET_CONFIG_NEED_IPV4=y
CONFIG_NET_CONFIG_SETTINGS=y

CONFIG_LWM2M=y
CONFIG_LWM2M_COAP_BLOCK_SIZE=512
CONFIG_LWM2M_IPSO_SUPPORT=y
CONFIG_LWM2M_IPSO_TEMP_SENSOR=y
CONFIG_LWM2M_IPSO_LIGHT_CONTROL=y
CONFIG_LWM2M_IPSO_TIMER=y
# compile test
CONFIG_LWM2M_CONN_MON_OBJ_SUPPORT=y
CONFIG_LWM2M_LOCATION_OBJ_SUPPORT=y
CONFIG_LWM2M_IPSO_ACCELEROMETER=y
CONFIG_LWM2M_IPSO_BUZZER=y
CONFIG_LWM2M_IPSO_ONOFF_SWITCH=y
CONFIG_LWM2M_IPSO_PUSH_BUTTON=y

CONFIG_NET_CONFIG_MY_IPV6_ADDR="2001:db8::1"
CONFIG_NET_CONFIG_PEER_IPV6_ADDR="2001:db8::2"
CONFIG_NET_CONFIG_MY_IPV4_ADDR="192.0.2.1"
CONFIG_NET_CONFIG_PEER_IPV4_ADDR="192.0.2.2"

[rlubos]

I'd bet it's a stack issue, I've been testing this sample a few days ago, and it turned out to have insufficient stack size for OpenThread in the default configuration:
#24840 (comment)

I'll verify it locally and report back.

[rlubos]

Yes, I confirm and recommend to increase CONFIG_MAIN_STACK_SIZE to 2048, OpenThread works way better.

[ghlualven]

@rlubos Thank you very much, I also verified this, the issue was fixed.