Zephyr CDC_ACM example unstable behaviour

[POG]

Hi,

We are currently developing a Sensors/USB/BLE/LTE-M1 product for a customer. The board is equipped with one nRF9160,for cloud communication, and one nRF52840, with a lot of sensors, BLE and USB. We have UART or SPI between nRF52840 and nRF9160. We use zephyr for both processors. Product is going into test in Q4 and in production in Q1 2020.

Now to the question:

I am currently trying to add CDC_ACM serial port behaviour to the nRF52840 processor. 

Setup for this example:

• Hardware:nRF52840 PCA10065 rev 1.0.0
• Example code: nsc\zephyr\samples\subsys\usb\cdc_acm\
• Board: nsc\zephyr\boards\arm\nrf52840_pca10056\
• I have disabled the mass storage device functionality according to Disabling the Mass Storage Device functionality

Problem: The reception of data is not stable. The test has been done on two different boards with similar issues.

Data sent to DUT:

0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789

Data received from DUT:

0123456789012345678901234567890123456789012345678901234567890123456789
012345678901234567890123456789012345678901234567890123456789012456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567891245689
0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789
012345678901234567890123456789012345678034703679456789

Do you have any hints what is wrong? Are there any known issues for nRF52840 causing this?

Are there anything else besides choosing example and board that I need to do? 

/ Per-Ola

[POG]

Hi,

I have look a bit deeper into this. This is what I have found.

• It seem like there is one callback for each received byte when the function cdc_acm_read_cb is called.
• Data in the rx_buf is not containing the expected data sent by the terminal program.

Proof:

I did some changes in the cdc_acm.c file to see what is happening:

Code:

The code is copying all received bytes from the dev_data->rx_buf array to the dev_data->rx_long_buf array.

dev_data->rx_long_index is used as index of the dev_data->rx_long_buf array.

dev_data->rx_int_counter is incremented for each call of the cdc_acm_read_cb function.

struct cdc_acm_dev_data_t

/* Device data structure */
struct cdc_acm_dev_data_t {
	/* USB device status code */
	enum usb_dc_status_code usb_status;
	/* Callback function pointer/arg */
	uart_irq_callback_user_data_t cb;
	void *cb_data;
	struct k_work cb_work;
	struct k_work tx_work;
	/* Tx ready status. Signals when */
	bool tx_ready;
	bool rx_ready;				/* Rx ready status */
	bool tx_irq_ena;			/* Tx interrupt enable status */
	bool rx_irq_ena;			/* Rx interrupt enable status */

    // Changes start  
    //************************************************************
    u16_t rx_long_index;
    u16_t rx_int_counter;
	u8_t rx_long_buf[CDC_ACM_BUFFER_SIZE * 10];
    //************************************************************
    // Changes end

	u8_t rx_buf[CDC_ACM_BUFFER_SIZE];	/* Internal RX buffer */
	u8_t tx_buf[CDC_ACM_BUFFER_SIZE];	/* Internal TX buffer */
	struct ring_buf *rx_ringbuf;
	struct ring_buf *tx_ringbuf;
	/* Interface data buffer */
	/* CDC ACM line coding properties. LE order */
	struct cdc_acm_line_coding line_coding;
	/* CDC ACM line state bitmap, DTE side */
	u8_t line_state;
	/* CDC ACM serial state bitmap, DCE side */
	u8_t serial_state;
	/* CDC ACM notification sent status */
	u8_t notification_sent;

	struct usb_dev_data common;
};

cdc_acm_read_cb

static void cdc_acm_read_cb(u8_t ep, int size, void *priv)
{
	struct cdc_acm_dev_data_t *dev_data = priv;
	size_t wrote;

	LOG_DBG("ep %x size %d dev_data %p rx_ringbuf space %u",
		ep, size, dev_data, ring_buf_space_get(dev_data->rx_ringbuf));

	if (size <= 0) {
		goto done;
	}

    // Changes start  
    //************************************************************
    dev_data->rx_int_counter++;

    for (u16_t index = 0; index<size ; index ++)
    {   
        if (sizeof(dev_data->rx_long_buf) > dev_data->rx_long_index)
        {
            dev_data->rx_long_buf[dev_data->rx_long_index++] = dev_data->rx_buf[index];
        }
 
    }
    //************************************************************
    // Changes end
    
	wrote = ring_buf_put(dev_data->rx_ringbuf, dev_data->rx_buf, size);
	if (wrote < size) {
		LOG_ERR("Ring buffer full, drop %d bytes", size - wrote);
	}

done:
	dev_data->rx_ready = true;

	/* Call callback only if rx irq ena */
	if (dev_data->cb && dev_data->rx_irq_ena) {
		k_work_submit(&dev_data->cb_work);
	}

	usb_transfer(ep, dev_data->rx_buf, sizeof(dev_data->rx_buf),
		     USB_TRANS_READ, cdc_acm_read_cb, dev_data);

}

cdc_acm_reset_port

static void cdc_acm_reset_port(struct cdc_acm_dev_data_t *dev_data)
{
	k_sem_give(&poll_wait_sem);
	dev_data->rx_ready = false;
	dev_data->tx_ready = false;
	dev_data->tx_irq_ena = false;
	dev_data->rx_irq_ena = false;
	dev_data->line_coding = (struct cdc_acm_line_coding)
				CDC_ACM_DEFAULT_BAUDRATE;
	dev_data->serial_state = 0;
	dev_data->line_state = 0;
	memset(&dev_data->rx_buf, 0, CDC_ACM_BUFFER_SIZE);

    // Changes start  
    //************************************************************
    dev_data->rx_long_index = 0;
    dev_data->rx_int_counter = 0;
    //************************************************************
    // Changes end

}

Data sent from terminal to DUT:

0123456789012345678901234567890123456789012345678901234567890123456789
0123456789012345678901234567890123456789012345678901234567890123456789

Data received in terminal from DUT:

0123456789012345678901235925926937046
012345678901234567894107529

Content after the test:

dev_data->rx_long_buf:  "0123456789012345678901235925926937046\r012345678901234567894107529"

Index of the rx_long_buf buffer: rx_long_index = 65

The callback has been called: dev_data->rx_int_counter = 65

The data in the dev_data->rx_long_buf is identical to the data received by the terminal program.

Conclusion so far. There is an incorrect behaviour when data is received. The loss of data is already there when the cdc_acm_read_cb is called.

Why is the callback called for each byte?

Why not fill the buffer?

The current flow of the program causes a lot of unnecessary extra workload.  I am using a baudrate of 115200. Too slow perhaps?

Any input? Is there something I have missed?

[Simon]

I am sorry for the long delay. I am currently looking into your issue and will try to provide you with an answer as soon as possible.

Best regards,
Simon

[Simon]

You should contact the Zephyr developers about this issue, the ones that wrote and are responsible for this sample. Use the community tools if you have Zephyr related questions:

• For reporting issues, see Zephyr GitHub repository issues.
• For asking questions or providing feedback, see Zephyr mailing lists.
• For interacting with users and developers directly, use the #zephyrproject channel on freenode.net.

Best regards,

Simon

[POG]

Hi again,

To give an answer to other developer with the same issue:

The reason why the cdc_acm example is behaving incorrectly for nRF52840, and probably other nRFs, is because it needs two defines to be configured in a proper way, either in the prj.conf file. 

CONFIG_CDC_ACM_IAD=y
CONFIG_USB_COMPOSITE_DEVICE=y

OR preferably in the boards\arm\nrf52840_pca10056\Kconfig.defconfig.

You might also be forced to set "#define RING_BUF_SIZE"  to a higher value than 1024 depending on how many bytes you send in a bunch.

/ Per-Ola