nrf52840 usb driver with openthread

[jwknaup]

Describe the bug
When attempting to use both the nrf52 usb serial device driver and openthread, the usb serial output prints very slowly with many dropped/garbled characters.

To Reproduce

• Start from the echo_client sample
• Enable openthread in the configuration as per the overlay-ot.conf file
• Enable USB in the configuration as per the usb/console sample .conf file
• Build and flash for the nrf52840_pca10056 v1.0.0

Expected behavior
It should print to console almost immediately:

**** Booting Zephyr OS zephyr-v1.14.0 *****                                     
32m[00:00:00.000,000] <inf> ieee802154_nrf5: nRF5 802154 radio initialized      
[00:00:00.004,821] <inf> net_l2_openthread: OpenThread version: OPENTHREAD/20187
[00:00:00.005,096] <inf> net_l2_openthread: Network name:   ot_zephyr           
[00:00:00.006,134] <inf> net_l2_openthread: State changed! Flags: 0x047f1309 Cu0
[00:00:00.007,141] <inf> net_l2_openthread: State changed! Flags: 0x00000004 Cu1
[00:00:00.007,232] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Cu1
[00:00:00.007,354] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Cu1
[00:00:00.007,507] <inf> net_l2_openthread: State changed! Flags: 0x00001000 Cu1
[00:00:00.007,629] <inf> net_l2_openthread: State changed! Flags: 0x00000010 Cu1
[00:00:00.007,690] <inf> net_l2_openthread: State changed! Flags: 0x00000020 Cu1
[00:00:00.013,977] <inf> net_config: Initializing network                       
[00:00:00.014,129] <inf> net_l2_openthread: State changed! Flags: 0x00000001 Cu1
[00:00:01.996,124] <inf> net_l2_openthread: State changed! Flags: 0x00000040 Cu1
[00:00:03.013,763] <inf> net_echo_client_sample: Starting...                    
[00:00:03.013,763] <inf> net_echo_client_sample: Run echo client                
[00:00:03.014,953] <dbg> net_echo_client_sample.send_udp_data: IPv6 UDP: Sent 7s
[00:00:04.055,755] <inf> net_l2_openthread: State changed! Flags: 0x000012a5 Cu4

In reality it prints very slowly (over a couple minutes):

                                                                               0
000000.0,66]<if>ne_l_oenhrad Oenhradvesin:OPNTRED/01892-032-g9d571;NOE;Ju 1 219m
                                                                               m
                                                                               m
[0:0:0.00,70 m<nf nt_2_pethea: tae haned Fags 000000 Crrntroe:                 m
00000001,12]<nf nt_2_pethea: Sat caned Fag:0x00100 uren rle:1m                  
[0:0:0.01,47]<n> etl2opntred:Sttechngd!Flgs 0000000 uren rl: 1[0:0:0.10,14 <if> 
[0:0:0.02,08 min> etcofi: niiaiingnewokme! las:0x00000 uret ol:                 
                                        [0:0:0.03,01]<if>ne_l_opntred:Sttechngd0
00000200,37] [0<in> etl2opntred:Sttechngd!Flgs 0x00040Curen rle 1[0             
[0:0:0.03,73]if> eteco_lintsapl: uneco len                                      
00000301464] [0mdb> eteco_lintsapl.sndup_at: Pv UP:Sen 13byes[0                 
00000421,03]<nf ne_l_oenhrad Sat hage! las:0x00125 uren rle 4[0                 
00001300,90]er>ne_ehoclen_smpe:UD Iv6 Dtapaketno rceved[0                       
0000:3.0448]<bg>neteco_ciet_amlesed_dpdaa:IP6 DP Snt45btes[0                    
[0:0:2299,90]<bg nt_ch_ciet_ampe.en_up_ata Iv6UD: en 61byes[0                   
[0:0:2.91,45 ;1mer> eteco_lintsapl: DPIP6:Daa acetnotreeied[0                   
00003298,02]<bg nt_ehoclen_smpe.ed_up_dta Iv6UDP Snt 21byes[0                   
00004297,62]er> eteco_lintsapl: DPIP6:Daa acet otreeied[0                       
000042.71252 mdg>ne_ehoclen_smpe.endud_dta Iv6UD: en 26 yts[0m                  
 ...                                                           

Impact
Cannot use nrf software usb with openthread applications

Environment (please complete the following information):

• OS: Ubuntu 18.04
• Zephyr SDK
• Zephyr v1.14.0
• nrf52840_pca10056 v1.0.0

Additional context
Running the same sample without openthread, the usb console works fine
Running the sample with openthread, without usb, and instead using the j-link usb connection, console works fine.
It is only the combination of openthread and usb that has issues.

My resulting configuration file looks like this

# Generic networking options
CONFIG_NETWORKING=y
CONFIG_NET_UDP=y
CONFIG_NET_TCP=y
CONFIG_NET_IPV6=y
CONFIG_NET_IPV4=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_SOCKETS_POLL_MAX=4

# Kernel options
CONFIG_MAIN_STACK_SIZE=2048
CONFIG_ENTROPY_GENERATOR=y
CONFIG_TEST_RANDOM_GENERATOR=y
CONFIG_INIT_STACKS=y

# Logging
CONFIG_NET_LOG=y
CONFIG_LOG=y
CONFIG_NET_STATISTICS=y
CONFIG_PRINTK=y

# Network buffers
CONFIG_NET_PKT_RX_COUNT=16
CONFIG_NET_PKT_TX_COUNT=16
CONFIG_NET_BUF_RX_COUNT=80
CONFIG_NET_BUF_TX_COUNT=80
CONFIG_NET_CONTEXT_NET_PKT_POOL=y

# IP address options
CONFIG_NET_IF_UNICAST_IPV6_ADDR_COUNT=3
CONFIG_NET_IF_MCAST_IPV6_ADDR_COUNT=4
CONFIG_NET_MAX_CONTEXTS=10

# Network shell
CONFIG_NET_SHELL=n

# The addresses are selected so that qemu<->qemu connectivity works ok.
# For linux<->qemu connectivity, create a new conf file and swap the
# addresses (so that peer address is ending to 2).
CONFIG_NET_CONFIG_SETTINGS=y
CONFIG_NET_CONFIG_MY_IPV6_ADDR="2001:db8::2"
CONFIG_NET_CONFIG_PEER_IPV6_ADDR="2001:db8::1"
CONFIG_NET_CONFIG_MY_IPV4_ADDR="192.0.2.2"
CONFIG_NET_CONFIG_PEER_IPV4_ADDR="192.0.2.1"

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_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::1"
CONFIG_NET_CONFIG_PEER_IPV6_ADDR="fdde:ad00:beef::2"

# 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 (flash for OT persistent storage)
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y

CONFIG_REBOOT=y

CONFIG_GPIO=y

CONFIG_USB=y
CONFIG_USB_DEVICE_STACK=y
CONFIG_USB_DEVICE_PRODUCT="Zephyr USB console sample"
CONFIG_USB_UART_CONSOLE=y

CONFIG_UART_INTERRUPT_DRIVEN=y
CONFIG_UART_LINE_CTRL=y
CONFIG_UART_CONSOLE_ON_DEV_NAME="CDC_ACM_0"

[jwknaup]

Any thoughts on this? If it's too low of a priority for anyone to work on, then I might attempt to tackle it myself although I'm not sure where to start given the complexity of the openthread codebase. But not being able to get logging output with openthread apps is making development pretty challenging

[rlubos]

Hi @jwknaup,

I've just tried to configure USB with OpenThread on current master. I've added the following configuration to the overlay-ot.conf in the echo_client sample:

CONFIG_USB=y
CONFIG_USB_DEVICE_STACK=y
CONFIG_USB_CDC_ACM=y
CONFIG_USB_DEVICE_PRODUCT="Zephyr OpenThread device"

CONFIG_UART_SHELL_ON_DEV_NAME="CDC_ACM_0"

With this configuration shell and logger over USB CDC worked fine for me. Two caveats though:

1. I've used nrf52840_pca10056 v1.1.0, could not find the v1.0.0,
2. For whatever reason, I needed to send any input over the shell, before I started receiving output on my terminal. I don't think though that's an OpenThread issue.

[jcorde]

Hi @jwknaup,

I was able to make Logging through USB work on a nrf52840_pca10059 (Dongle) but OpenThread's connection range was reduced from 20 meters to 1 meter.

I suppose it is somehow related to #11694, as it is necessary for me to disable UART interrupt for it to work properly:

CONFIG_UART_INTERRUPT_DRIVEN=n
CONFIG_UART_0_NRF_UARTE=n
CONFIG_UART_0_INTERRUPT_DRIVEN=n

[jwknaup]

Thanks @rlubos for the correct config. I guess I needed to use the usb uart shell instead of the console. I think we can close this

@jcorde I did not notice such a significant reduction in range, thank goodness!

[rlubos]

@jwknaup You're correct, Zephyr's OpenThread port is integrated with shell/logger subsystem, not the console.

[rlubos]

Issue resolved.

[nikhil30081995]

Hello @rlubos
The above configuration mentioned by you help me enable the openthread CLI, were i can enter the ot cli commands. But if i want to print out any log how can i do that ? Like for say if i want to print out sensor data on terminal will printf function with stdio library work.

[rlubos]

As for the printf() I'm not sure if it's possible to route it via the same USB_CDC port as shell w/o disrupting each other. But it's possible to route logger output to the shell backend with CONFIG_SHELL_LOG_BACKEND=y option.

[nikhil30081995]

Hey @rlubos
Thanks for a quick reply. Can you please look at this file and tell what are things i should comment out to print the data in the above shell configurations you mentioned.
`

CONFIG_COAP_SERVER_LOG_LEVEL_DBG=y
CONFIG_OT_COAP_UTILS_LOG_LEVEL_DBG=y

CONFIG_NET_SHELL=y
CONFIG_SHELL_ARGC_MAX=26
CONFIG_SHELL_CMD_BUFF_SIZE=416

CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_NET_SOCKETS_POLL_MAX=4

CONFIG_OPENTHREAD_MASTERKEY="00:11:22:33:44:55:66:77:88:99:aa:bb:cc:dd:ee:ff"

CONFIG_USE_SEGGER_RTT=y
CONFIG_RTT_CONSOLE=y
CONFIG_UART_CONSOLE=n

CONFIG_LOG=y
CONFIG_OPENTHREAD_DEBUG=y
CONFIG_LOG_BACKEND_RTT=y

#CONFIG_OPENTHREAD_LOG_LEVEL_DEBG=n
#CONFIG_LOG_STRDUP_BUF_COUNT=1024
#CONFIG_LOG_STRDUP_MAX_STRING=128
#CONFIG_OPENTHREAD_L2_LOG_LEVEL_DBG=n
#CONFIG_OPENTHREAD_L2_DEBUG_DUMP_15_4=n

CONFIG_GPIO=y
CONFIG_SERIAL=y
CONFIG_I2C=y
CONFIG_I2C_1=y
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y

CONFIG_USB=y
CONFIG_USB_DEVICE_STACK=y
CONFIG_USB_CDC_ACM=y
CONFIG_USB_DEVICE_PRODUCT="Zephyr OpenThread device"
CONFIG_UART_SHELL_ON_DEV_NAME="CDC_ACM_0"

I tried every possible thing because i wasn't able to print data on my serial terminal via USB. Currently i am able to receive log info on debug terminal using RTT as i have enabled that. If i just disable RTT i wasn't able to receive log on terminal

[rlubos]

And did you tried to enable CONFIG_SHELL_LOG_BACKEND=y? Actually, it should be enabled by default unless you don't satisfy it's dependencies:

config SHELL_LOG_BACKEND
	bool "Enable shell log backend"
	depends on LOG && !LOG_MINIMAL
	default y if LOG

It seems that the config you shared is not a complete one (I see some OT required configs missing). Are you building in NCS context? I know it has some default config file, which used to enable LOG_MINIMAL. I'm not sure why does the shell backend has !LOG_MINIMAL dependency, but it won't be possible to enable shell backend with LOG_MINIMAL enabled.

[nikhil30081995]

Hello @rlubos
The above file was my proj.conf file.
I haven't changed anything in the ot-config present in common folder.

Here is my ot-default-config file from common folder:

`

CONFIG_NCS_SAMPLES_DEFAULTS=y

CONFIG_NEWLIB_LIBC=y

Enable floating point Hard ABI
CONFIG_FPU=y
CONFIG_FP_HARDABI=y

Generic networking options
CONFIG_NETWORKING=y
CONFIG_NET_CONNECTION_MANAGER=y

Kernel options
CONFIG_MAIN_STACK_SIZE=8192
CONFIG_INIT_STACKS=y

Increase set for threads with meta-irq priority
CONFIG_NUM_METAIRQ_PRIORITIES=1

Logging
CONFIG_NET_LOG=y
CONFIG_NET_STATISTICS=y

Disable certain parts of Zephyr IPv6 stack
CONFIG_NET_IPV6_NBR_CACHE=n
CONFIG_NET_IPV6_MLD=n

Stack sizes configuration
CONFIG_NET_TX_STACK_SIZE=1200
CONFIG_NET_RX_STACK_SIZE=1500

Network buffers
CONFIG_NET_PKT_RX_COUNT=10
CONFIG_NET_PKT_TX_COUNT=16
CONFIG_NET_BUF_RX_COUNT=16
CONFIG_NET_BUF_TX_COUNT=16

L2 OpenThread enabling
CONFIG_NET_L2_OPENTHREAD=y
CONFIG_OPENTHREAD_DEBUG=y
CONFIG_OPENTHREAD_L2_DEBUG=y
CONFIG_OPENTHREAD_L2_LOG_LEVEL_INF=y

Disable OpenThread autostart
CONFIG_OPENTHREAD_MANUAL_START=y

Disable vanilla mbedtls in favor of custom backends
CONFIG_OPENTHREAD_MBEDTLS=n

Disable unneeded mbedtls modules
CONFIG_MBEDTLS_CIPHER_MODE_CBC=n
CONFIG_MBEDTLS_CIPHER_MODE_CTR=n
CONFIG_MBEDTLS_CIPHER_MODE_CFB=n
CONFIG_MBEDTLS_CIPHER_MODE_OFB=n
CONFIG_MBEDTLS_CIPHER_MODE_XTS=n
CONFIG_MBEDTLS_GCM_C=n
CONFIG_MBEDTLS_CHACHA20_C=n
CONFIG_MBEDTLS_POLY1305_C=n
CONFIG_MBEDTLS_CHACHAPOLY_C=n
CONFIG_MBEDTLS_DHM_C=n
CONFIG_MBEDTLS_RSA_C=n
CONFIG_MBEDTLS_SHA1_C=n
CONFIG_MBEDTLS_SHA512_C=n
CONFIG_MBEDTLS_HEAP_SIZE=10240

`

And in last reply i mentioned was proj.conf i enabled RTT because i wasn't able to enable the USB port. By your configurations i was able to enable the USB. I will enabling logs for debugging purpose only.

I will try this CONFIG_SHELL_LOG_BACKEND=y and revert you back. I would also like to know is there any way to print out my sensor data on USB without displaying other logs in final product.

[rlubos]

Note that CONFIG_NCS_SAMPLES_DEFAULTS=y enables CONFIG_LOG_MINIMAL which is in conflict with CONFIG_SHELL_LOG_BACKEND as stated earlier. You should remove that line (or override CONFIG_LOG_MINIMAL=n in your project file).

[nikhil30081995]

Hey @rlubos ,
Would like to know will the above configuration help me to just print out the sensor data on USB CDC ? I am finding it hard to integrate USB CDC example with Openthread example.

[rlubos]

@nikhil30081995 Please refer to the latest version of the NCS CLI sample:
https://github.com/nrfconnect/sdk-nrf/tree/master/samples/openthread/cli
The latest version provides overlay-usb.conf which enables USB CDC for shell and logging in the sample.

[nikhil30081995]

Yesterday only i installed NCS using manual steps on ubuntu. nrf version is 1.6.0 in that i don't see overlay file for USB in CLI example. Will the above mentioned overlay file work with my version too?

[rlubos]

Yesterday only i installed NCS using manual steps on ubuntu. nrf version is 1.6.0 in that i don't see overlay file for USB in CLI example. Will the above mentioned overlay file work with my version too?

I don't know that, the overlay was added after 1.6.0 release. You can simply use the latest master.

[nikhil30081995]

Okay @rlubos
I got it working thanks just by adding USB overlay file directly.

Just to add i can use the same interface to print my data on the terminal right?

[rlubos]

If you use logger, yes.

[nikhil30081995]

By logger you mean the steps you mentioned above ?

[rlubos]

By logger I mean the Zephyr logger module. You print logs with with LOG_*() macros. Again, please refer to the sample:
https://github.com/nrfconnect/sdk-nrf/blob/master/samples/openthread/cli/src/main.c#L69

[nikhil30081995]

Hello @rlubos
I checked out the examples you mentioned but it's from master directory and we have already developed our application using ncs 1.6.0. So we can't just move to newer sdk version as there can be issues with dependency.

My current application is configured in such a way that the logs are enabled on the JLink RTT Viewer. Also using printf i am able to printf on RTT Viewer . I need printf to work because i don't want unnecessary data like to get printed with my sensor data.

So i would just like to shift from RTT Viewer to USB CDC.

[rlubos]

I'm not that familiar with stdout configuration, so I suggest you experiment with Kconfig options on your own or ask on slack on how to enable stdout on USB CDC device.

To my knowledge, you need to enable appropriate CONSOLE in order to get the stdout to work correctly, so I'd double check if CONFIG_UART_CONSOLE is enabled in your case and CONFIG_UART_CONSOLE_ON_DEV_NAME is set correctly to the USB CDC device. It also seems that CONFIG_SHELL_BACKEND_RTT enforces CONFIG_RTT_CONSOLE which would likely interfere with the UART console, so make sure it's disabled.

[nikhil30081995]

Hey @rlubos
I tried the method you mentioned previously of using LOG_* to print out the data. I have disabled the minimal config in configuration file. And now i am using printk functions to output the sensor data on terminal.

But now the issue arrives when reading data using python script. The printk function goes through LOGs, so basically 9-10 data samples are printed at a time. So which makes python serial readline difficult to read data from terminal as the data are in bulk. So can you suggest me how to print data using LOG/printk one at a time instead of reading data in buffer and writing it after 1second.

`dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'\x1b[JBLACKLK1328.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'[m\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'1328.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'CKLK1328.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'LACKLK1328.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'1328.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'1;32m\x1b[m\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'[JBLACKLK1328.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'28.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'ACKLK1328.91 999.80 50.43\r\n'

dnk121@DNK121:~/Nikhil/Project/S-Node$ python3 data_extractioon.py
b'\r\x1b[1;32m\x1b[m\r\n'

`

`
from collections import deque
from serial import Serial

ser = Serial('/dev/ttyACM0',115200,timeout=0.1)
ser.flushInput()

ser_bytes = ser.readline()
print(ser_bytes)
`

[rlubos]

To be honest, I don't quite understand how receiving data in bulk could impair the serial readline operation - it should only read the data up to the newline character (note that printk() would append the message with a newline char - you need to make sure it's a part of the string.

But if you really want to disable the logger functionality to accumulate the data, either disable the feature itself (CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD=0) or switch to immediate mode (CONFIG_LOG_MODE_IMMEDIATE=y). Note, that in the immediate mode the log will be printed out from the thread it's posted, causing delays.

And, please, open a separate issue if you have more questions, we're deviating from the original topic a lot now.