Zephyr: usb cdc acm fails when writing big chunks of data on stm32

[StefJar]

I have problems when sending bigger amounts of data via
uart_poll_out
it fails after a short time with:
usb_dc_stm32: Unable to write ep 0x82 (-16)

I am using a hybrid io approach:
The rx on the CDC-ACM works on interrupt base. The tx is done via polling.
The CDC-ACM is setup without any flow control only the baudrate is set.

For testing I changed to a fully interrupt driven approach. Means I send the the data via uart_fifo_fill. Now the tx works fine but the rx seems to be blocked.

some code spinets:

setup:

typedef struct usbACMs {
    struct device * uart;
    struct k_msgq rxMQ;
    volatile bool txDone;
} usbACM_t;

static usbACM_t usbACM;
static char __aligned(4) usbACM_rx_buffer [sizeof(u8_t) * USBACM_RX_BUFFERSIZE];

static K_SEM_DEFINE(usbACMStartSem, 0, 1);

int usbACM_init(void) {
    u32_t baudrate = 0;
    int ret;

    LOG_INF("init USB ACM");
    memset(&usbACM, 0, sizeof(usbACM));

    k_msgq_init(&usbACM.rxMQ, usbACM_rx_buffer, sizeof(u8_t), sizeof(usbACM_rx_buffer)/sizeof(u8_t));

    usbACM.uart = device_get_binding(CONFIG_CDC_ACM_PORT_NAME_0);
    if (!usbACM.uart) {
        LOG_ERR("CDC ACM device not found");
        return -1;
    }

    ret = uart_line_ctrl_get(usbACM.uart, LINE_CTRL_BAUD_RATE, &baudrate);
    if (ret) {
        LOG_ERR("Failed to get baudrate, ret code %d", ret);
        return -2;
    } else {
        LOG_INF("Baudrate detected: %d", baudrate);
    }

    usbACM.uart = device_get_binding(CONFIG_CDC_ACM_PORT_NAME_0);
    if (!usbACM.uart) {
        LOG_ERR("CDC ACM device not found");
        return -1;
    }

    ret = uart_line_ctrl_get(usbACM.uart, LINE_CTRL_BAUD_RATE, &baudrate);
    if (ret) {
        LOG_ERR("Failed to get baudrate, ret code %d", ret);
        return -2;
    } else {
        LOG_INF("Baudrate detected: %d", baudrate);
    }
    // try to set baudrate
    baudrate = 115200;
    LOG_DBG("try to set baudrate to %d", baudrate);
    ret = uart_line_ctrl_set(usbACM.uart, LINE_CTRL_BAUD_RATE, baudrate);
    if (ret) {
        LOG_ERR("Failed to set baudrate to %d, ret code %d", baudrate, ret);
        return -3;
    } else {
        uart_line_ctrl_get(usbACM.uart, LINE_CTRL_BAUD_RATE, &baudrate);
        LOG_INF("Baudrate set to %d", baudrate);
    }

    uart_irq_callback_set(usbACM.uart, usbACM_interrupt_handler);
    uart_irq_rx_enable(usbACM.uart);

    k_sem_give(&usbACMStartSem);
    return 0;
}

isr:

static void usbACM_interrupt_handler(struct device *dev)
{
    u8_t c;
    uart_irq_update(dev);

    while (uart_irq_rx_ready(dev)) {
        // get char
        uart_fifo_read(dev, &c, 1);
        // and store
        if (k_msgq_put(&usbACM.rxMQ, &c, K_NO_WAIT) != 0) {
            LOG_ERR("rx buffer overflow");
        }
    }
/*
    if (uart_irq_tx_ready(dev)) {
        usbACM.txDone = true;
    }
*/
}

tx:

static void usbACM_tx_helper_sendData(u8_t * pD, u8_t N) {
    u8_t i;
    for (i = 0; i < N; i++) {
        uart_poll_out(usbACM.uart, *pD);
        pD++;
    }
/*
    uart_irq_tx_enable(usbACM.uart);
    int am;

    while (N) {
        usbACM.txDone = false;
        am = uart_fifo_fill(usbACM.uart, (const u8_t *)pD, (int) N);
        N -= am;
        pD += am;
        while (usbACM.txDone == false) {
            k_sleep(1);
        }
    }
    uart_irq_tx_disable(usbACM.uart);
*/
}

rx thread:

void usbACM_rxThread(void) {
char c;
    LOG_INF("start usb rx thread");

    LOG_DBG("wait for init");
    k_sem_take(&usbACMStartSem, K_FOREVER);
    LOG_DBG("usb rx init done");

    for(;;) {
    if (k_msgq_get(&usbACM.rxMQ, &c, K_FOREVER)) {
        continue;
    }
LOG_DBG("got 0x%x",(unsigned int)c);
    }
}

[carlescufi]

@StefJar could you please provide a reproducible sample in a GitHub repo that allows @finikorg to reproduce locally in order to fix this?

[StefJar]

I tried to get it down to a simple example.
So I setup the usb ACM & create an simple rx thread polling on input. In this system are running I2C, SPIs, ADC and UART & DMA transfers. I am running the code on a stm32F412.

To test some code snippet:

#include <zephyr.h>
#include <device.h>
#include <uart.h>

#include <logging/log.h>
LOG_MODULE_REGISTER(USB_ACM, 4);

typedef struct usbACMs {
    struct device * uart;
} usbACM_t;

static usbACM_t usbACM;

static K_SEM_DEFINE(usbACMStartSem, 0, 1);

int usbACM_init(void) {
    u32_t baudrate = 0;
    int ret;

    LOG_INF("init USB ACM");
    memset(&usbACM, 0, sizeof(usbACM));

    usbACM.uart = device_get_binding(CONFIG_CDC_ACM_PORT_NAME_0);
    if (!usbACM.uart) {
        LOG_ERR("CDC ACM device not found");
        return -1;
    }

    ret = uart_line_ctrl_get(usbACM.uart, LINE_CTRL_BAUD_RATE, &baudrate);
    if (ret) {
        LOG_ERR("Failed to get baudrate, ret code %d", ret);
        return -2;
    } else {
        LOG_INF("Baudrate detected: %d", baudrate);
    }
    // try to set baudrate
    baudrate = 115200;
    LOG_DBG("try to set baudrate to %d", baudrate);
    ret = uart_line_ctrl_set(usbACM.uart, LINE_CTRL_BAUD_RATE, baudrate);
    if (ret) {
        LOG_ERR("Failed to set baudrate to %d, ret code %d", baudrate, ret);
        return -3;
    } else {
        uart_line_ctrl_get(usbACM.uart, LINE_CTRL_BAUD_RATE, &baudrate);
        LOG_INF("Baudrate set to %d", baudrate);
    }

    k_sem_give(&usbACMStartSem);
    return 0;
}

void usbACM_rxThread(void) {
    char c;
    LOG_INF("start usb rx thread");

    LOG_DBG("wait for init");
    k_sem_take(&usbACMStartSem, K_FOREVER);
    LOG_DBG("usb rx init done");
    for(;;) {
        if (0 == uart_poll_in(usbACM.uart, &c)) {
            LOG_ERR("rx: 0x%X", (unsigned int) c);
        } else {
            k_yield();
        }
    }
}

K_THREAD_DEFINE(usbACMRXThread_id, 1024, usbACM_rxThread, NULL, NULL, NULL, THREAD_PRIO_ACM, 0, K_NO_WAIT);

no bytes are coming through

[finikorg]

@StefJar Thanks, I will check this issue, I am thinking about using ring_buf for TX path also.

[StefJar]

small update. I changed a bit the test code to make it more convinent with the sample. I am attaching it at the end of the post.

First experiences:

• waiting for data ready leading to working rx
• the tx is working a bit longer till it breaks
• after tx error " usb_dc_stm32: Unable to write ep 0x82 (-16)" the tx never recovers

@finikorg I saw that you done some changes to the usb_stm32 code. When these ones are getting merged to the main zephyr git?
The code below should work much better than the initial ones. Setting semaphores is not blocking the kernel and the ringbuffers should be a efficient mechanism to copy the data form kernel space to user space.

My test code:

/*
 * usbACM.c
 *
 *  Created on: 25 Feb 2019
 *      Author: Stefan Jaritz
 */
#include <zephyr.h>
#include <ring_buffer.h>
#include <device.h>
#include <uart.h>

#include <logging/log.h>

LOG_MODULE_REGISTER(USB_ACM, 4);

#include "usbACM.h"

#define USBACM_RX_BYTES_AMOUNT 512

typedef struct usbACMs {
    struct device * uart;

    struct {
        struct ring_buf rxRB;
        struct k_sem rxSem;
        u8_t buffer[32];
        u8_t rxBuffer [USBACM_RX_BYTES_AMOUNT];
    } rx;

    struct {
        unsigned int N;
        u8_t * pD;
        struct k_sem done;
        struct k_mutex guardM;
    } tx;
} usbACM_t;

static usbACM_t usbACM;

static K_SEM_DEFINE(usbACMStartSem, 0, 1);

static void usbACM_isr(struct device *dev) {
    int am;

    uart_irq_update(dev);

    if (uart_irq_tx_ready(dev)) {
        k_sem_give(&usbACM.tx.done);
    }

    if (uart_irq_rx_ready(dev)) {
        while(true) {
            am = uart_fifo_read(dev,usbACM.rx.buffer, sizeof(usbACM.rx.buffer));
            if (am) {
                if (am != ring_buf_put(&usbACM.rx.rxRB, usbACM.rx.buffer, am)) {
                    LOG_ERR("usb acm rx buffer overflow");
                }
            } else {
                break;
            }
        }
        k_sem_give(&usbACM.rx.rxSem);
    }
}

static void usbACM_tx_helper_sendData(u8_t * pD, u8_t N) {
    int am;

    k_mutex_lock(&usbACM.tx.guardM, K_FOREVER);
    uart_irq_tx_enable(usbACM.uart);

    while (N) {
        am = uart_fifo_fill(usbACM.uart, (const u8_t *)pD, N);
        k_sem_take(&usbACM.tx.done, K_FOREVER);
        N -= (u8_t)am;
        pD += am;
    }
    uart_irq_tx_disable(usbACM.uart);
    k_mutex_unlock(&usbACM.tx.guardM);
}

int usbACM_init(void) {
    u32_t baudrate = 0;
    int ret;

    LOG_INF("init USB ACM");
    memset(&usbACM, 0, sizeof(usbACM));

    k_sem_init(&usbACM.tx.done,0,0xFFFF);
    k_mutex_init(&usbACM.tx.guardM);
    usbACM.tx.N = 0;
    usbACM.tx.pD = NULL;

    ring_buf_init(&usbACM.rx.rxRB, sizeof(usbACM.rx.rxBuffer), usbACM.rx.rxBuffer);
    k_sem_init(&usbACM.rx.rxSem,0,sizeof(usbACM.rx.rxBuffer));

    usbACM.uart = device_get_binding(CONFIG_CDC_ACM_PORT_NAME_0);
    if (!usbACM.uart) {
        LOG_ERR("CDC ACM device not found");
        return -1;
    }

    ret = uart_line_ctrl_get(usbACM.uart, LINE_CTRL_BAUD_RATE, &baudrate);
    if (ret) {
        LOG_ERR("Failed to get baudrate, ret code %d", ret);
        return -2;
    } else {
        LOG_INF("Baudrate detected: %d", baudrate);
    }
    // try to set baudrate
    baudrate = 115200;
    LOG_DBG("try to set baudrate to %d", baudrate);
    ret = uart_line_ctrl_set(usbACM.uart, LINE_CTRL_BAUD_RATE, baudrate);
    if (ret) {
        LOG_ERR("Failed to set baudrate to %d, ret code %d", baudrate, ret);
        return -3;
    } else {
        uart_line_ctrl_get(usbACM.uart, LINE_CTRL_BAUD_RATE, &baudrate);
        LOG_INF("Baudrate set to %d", baudrate);
    }

    uart_irq_callback_set(usbACM.uart, usbACM_isr);
    uart_irq_rx_enable(usbACM.uart);

    k_sem_give(&usbACMStartSem);
    return 0;
}

void usbACM_rxThread(void) {
    char c;
    u32_t dtr;
    char rxB[32];
    u32_t am;

    LOG_INF("start usb rx thread");

    LOG_DBG("wait for init");
    k_sem_take(&usbACMStartSem, K_FOREVER);
    LOG_DBG("usb rx init done");

    LOG_DBG("Wait for DTR");
    while (1) {
        uart_line_ctrl_get(usbACM.uart, LINE_CTRL_DTR, &dtr);
        if (dtr) break;
        k_sleep(K_MSEC(10));
    }
    LOG_DBG("DTR set");

    for(;;) {
        am = ring_buf_get(&usbACM.rx.rxRB,rxB, 1);
        if (am == 0) {
            if (k_sem_take(&usbACM.rx.rxSem, K_FOREVER)) {
                LOG_ERR("failed to get sem");
                continue;
            }
            continue;
        }
        LOG_DBG("0x%X",(unsigned int) rxB[0]);
    }
}

[finikorg]

BTW: I have RFC PR #15511.

[StefJar]

merci for letting me know. I will test the code, when it gets merged into master

[finikorg]

I found an issue related to this error. After sending packet multiple of 64 bytes we add zero length packet for which stm32 driver does not generate callback and we do not give semaphore ep_state->write_sem. So after that we get error <err> usb_dc_stm32: Unable to write ep 0x82 (-16).
@ydamigos @loicpoulain could you verify that?

[finikorg]

diff --git a/drivers/usb/device/usb_dc_stm32.c b/drivers/usb/device/usb_dc_stm32.c
index 4208b4c95d..0b63a548e2 100644
--- a/drivers/usb/device/usb_dc_stm32.c
+++ b/drivers/usb/device/usb_dc_stm32.c
@@ -737,11 +737,8 @@ int usb_dc_ep_write(const u8_t ep, const u8_t *const data,
                return -EINVAL;
        }

-       ret = k_sem_take(&ep_state->write_sem, K_NO_WAIT);
-       if (ret) {
-               LOG_ERR("Unable to write ep 0x%02x (%d)", ep, ret);
-               return ret;
-       }
+
+       k_sem_take(&ep_state->write_sem, K_FOREVER);

        if (!k_is_in_isr()) {
                irq_disable(DT_USB_IRQ);

@StefJar does this fix the issue?

[StefJar]

diff --git a/drivers/usb/device/usb_dc_stm32.c b/drivers/usb/device/usb_dc_stm32.c
index 4208b4c95d..0b63a548e2 100644
--- a/drivers/usb/device/usb_dc_stm32.c
+++ b/drivers/usb/device/usb_dc_stm32.c
@@ -737,11 +737,8 @@ int usb_dc_ep_write(const u8_t ep, const u8_t *const data,
                return -EINVAL;
        }

-       ret = k_sem_take(&ep_state->write_sem, K_NO_WAIT);
-       if (ret) {
-               LOG_ERR("Unable to write ep 0x%02x (%d)", ep, ret);
-               return ret;
-       }
+
+       k_sem_take(&ep_state->write_sem, K_FOREVER);

        if (!k_is_in_isr()) {
                irq_disable(DT_USB_IRQ);

@StefJar does this fix the issue?

This fixes my issue :D

[finikorg]

However other USB drivers return in such case -EAGAIN, so I have another fix

[loicpoulain]

diff --git a/drivers/usb/device/usb_dc_stm32.c b/drivers/usb/device/usb_dc_stm32.c
index 4208b4c95d..0b63a548e2 100644
--- a/drivers/usb/device/usb_dc_stm32.c
+++ b/drivers/usb/device/usb_dc_stm32.c
@@ -737,11 +737,8 @@ int usb_dc_ep_write(const u8_t ep, const u8_t *const data,
                return -EINVAL;
        }

-       ret = k_sem_take(&ep_state->write_sem, K_NO_WAIT);
-       if (ret) {
-               LOG_ERR("Unable to write ep 0x%02x (%d)", ep, ret);
-               return ret;
-       }
+
+       k_sem_take(&ep_state->write_sem, K_FOREVER);

        if (!k_is_in_isr()) {
                irq_disable(DT_USB_IRQ);

@StefJar does this fix the issue?

This fixes my issue :D

note that ep_write can be called in irq context, if the the caller call write before the previous one has been completed, then it's probably a bug in the caller itself.

I found an issue related to this error. After sending packet multiple of 64 bytes we add zero length packet for which stm32 driver does not generate callback and we do not give semaphore ep_state->write_sem. So after that we get error <err> usb_dc_stm32: Unable to write ep 0x82 (-16).
@ydamigos @loicpoulain could you verify that?

I'm going to have a look.