CDC Device initial sent data lost if application sends data immediately after tud_cdc_connected().

[andrewleech]

I'm working on adding a feature in micropython (tinyusb device) where a welcome banner is printed over CDC when the host opens the serial port.

At startup, the device essentially blocks on trying to send a newline over the com port, retrying until tud_cdc_connected() after which a few lines of text are sent and the device continues its normal startup.

However, this banner text never shows on most terminal applications I've tried.

I initially found that adding a delay of at least 4ms after the initial tud_cdc_connected() == True "fixed" the problem, such that the banner text then comes through just fine.

Further testing showed though even without the delay, the banner would show up when using:
cu -l /dev/ttyACM0
Whereas testing in minicom, mpremote and (windows python based) tinycom all connected to the device fine, but never showed the banner. Any text I sent immediately after connection was lost, but ongoing comminuted communication both ways is fine.

Eventually I narrowed it down to:
• working: screen /dev/ttyACM0
• not working: screen /dev/ttyACM0 115200

Confirmed with the following in python:
• working: >>> import serial; p=serial.Serial("/dev/ttyACM0"); p.read(p.inWaiting())
• not working: >>> import serial; p=serial.Serial("/dev/ttyACM0", baudrate=115200); p.read(p.inWaiting())

Note the tinyusb application on device never uses the baud rate for anything and ongoing communication works fine regardless of the set baud rate.

It appears to me that if the baud rate is set during the process of the the host opening the port, this presumably happens shortly after the DTR signal that tud_cdc_connected() responds to, then tinyusb clears any outgoing buffers that were loaded between DTR and baud setting?

Does this sound likely / expected between behaviour?

Snippets of code involved:

// Send string
mp_uint_t mp_hal_stdout_tx_str(const char *str) {
    mp_uint_t len = strlen(str);
    mp_uint_t ret = len;
    bool did_write = false;
   
    #if MICROPY_HW_USB_CDC
    if (tud_cdc_connected()) {
        size_t i = 0;
        while (i < len) {
            uint32_t n = len - i;
            if (n > CFG_TUD_CDC_EP_BUFSIZE) {
                n = CFG_TUD_CDC_EP_BUFSIZE;
            }
            int timeout = 0;
            // Wait with a max of USC_CDC_TIMEOUT ms
            while (n > tud_cdc_write_available() && timeout++ < MICROPY_HW_USB_CDC_TX_TIMEOUT) {
                mp_event_wait_ms(1);

                // Explicitly run the USB stack as the scheduler may be locked (eg we
                // are in an interrupt handler), while there is data pending.
                //mp_usbd_task();
                tud_task_ext(10, false);
            }
            if (timeout >= MICROPY_HW_USB_CDC_TX_TIMEOUT) {
                ret = i;
                break;
            }
            uint32_t n2 = tud_cdc_write(str + i, n);
            tud_cdc_write_flush();
            // tud_task_ext(10, false);
            
            i += n2;
        }
        ret = MIN(i, ret);
        did_write = true;
    }
    #endif

    return did_write ? ret : 0;
}

void pyexec_print_banner() {
    while (!mp_hal_stdout_tx_str("\r\n")) {
        // Run background / idle tasks 
        MICROPY_EVENT_POLL_HOOK
    }
    // If I add this delay the text below always comes through.
    //mp_hal_delay_ms(4);
    
    mp_hal_stdout_tx_str(MICROPY_BANNER_NAME_AND_VERSION);
    mp_hal_stdout_tx_str("; " MICROPY_BANNER_MACHINE);
    mp_hal_stdout_tx_str("\r\n");
    #if MICROPY_PY_BUILTINS_HELP
    mp_hal_stdout_tx_str("Type \"help()\" for more information.\r\n");
    #endif
}

[andrewleech]

Update to this; I'm not sure that the setting or not setting of baudrate is the key difference for working / not working anymore. After updating to the latest master tinyusb it's not as simple as this.

After cracking out my USB Analyser (USBLyzer), the problem appears to be simply timing based.

tud_cdc_connected() returns true as soon as DTR is enabled in a Set Line Coding call from host.
If I TX data / call tud_cdc_write_flush(); as soon as this returns true, the data is not seen on the host.
If I wait ~ 5 ms before the tud_cdc_write_flush(); the data is seen correctly.

snippet of working case:

same snippet of non-working case:

The working case has a 5ms delay after tud_cdc_connected() before tud_cdc_write_flush();, the non-working case does not.
I can see the Set Line Coding that presumably contains the DTR true, followed by a final Get Line Coding call. If the data transfer is started before the final Get Line Coding, the host application never receives the data on the com port.

I loathe the idea of needing to leave a static delay in the device application codebase as it's inefficient and unlikely to work in all cases.

Is this kind of "dropped data if sent before final get line coding" somewhat expected behaviour? Is there any way for an application to see / wait for a final get line coding call before proceeding, or should TinyUSB perhaps track this after a set line coding call before flagging tud_cdc_connected() as true?

[andrewleech]

This is probably a more helpful log - as above in the non-working case the application sends tx data as soon as DTR is set high which seems to clash with the remaining CDC control requests.

Working

Non-Working

USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received 21 20 00 00 00 00 07 00 CDC control request Set Line Coding Queue EP 00 with 7 bytes ... USBD Xfer Complete on EP 00 with 7 bytes 0000: 80 25 00 00 00 00 08 CDC control complete Queue EP 80 with 0 bytes ... USBD Xfer Complete on EP 80 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received 21 22 03 00 00 00 00 00 CDC control request Queue EP 80 with 0 bytes ... USBD Xfer Complete on EP 80 with 0 bytes Set Control Line State: DTR = 1, RTS = 1 USBD Setup Received 21 20 00 00 00 00 07 00 CDC control request Set Line Coding Queue EP 00 with 7 bytes ... USBD Xfer Complete on EP 00 with 7 bytes 0000: 80 25 00 00 00 00 08 CDC control complete Queue EP 80 with 0 bytes ... USBD Xfer Complete on EP 80 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes Queue EP 82 with 64 bytes ... USBD Xfer Complete on EP 82 with 64 bytes CDC xfer callback Queue EP 82 with 64 bytes ... USBD Xfer Complete on EP 82 with 64 bytes CDC xfer callback Queue EP 82 with 4 bytes ... USBD Xfer Complete on EP 82 with 4 bytes CDC xfer callback

USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received 21 20 00 00 00 00 07 00 CDC control request Set Line Coding Queue EP 00 with 7 bytes ... USBD Xfer Complete on EP 00 with 7 bytes 0000: 80 25 00 00 00 00 08 CDC control complete Queue EP 80 with 0 bytes ... USBD Xfer Complete on EP 80 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes USBD Setup Received 21 22 03 00 00 00 00 00 CDC control request Queue EP 80 with 0 bytes ... USBD Xfer Complete on EP 80 with 0 bytes Set Control Line State: DTR = 1, RTS = 1 Queue EP 82 with 64 bytes ... USBD Setup Received 21 20 00 00 00 00 07 00 CDC control request Set Line Coding Queue EP 00 with 7 bytes ... USBD Xfer Complete on EP 82 with 64 bytes CDC xfer callback Queue EP 82 with 64 bytes ... USBD Xfer Complete on EP 00 with 7 bytes 0000: 80 25 00 00 00 00 08 CDC control complete Queue EP 80 with 0 bytes ... USBD Xfer Complete on EP 82 with 64 bytes CDC xfer callback Queue EP 82 with 4 bytes ... USBD Xfer Complete on EP 80 with 0 bytes USBD Setup Received A1 21 00 00 00 00 07 00 CDC control request Get Line Coding Queue EP 80 with 7 bytes ... USBD Xfer Complete on EP 82 with 4 bytes CDC xfer callback USBD Xfer Complete on EP 80 with 7 bytes CDC control complete Queue EP 00 with 0 bytes ... USBD Xfer Complete on EP 00 with 0 bytes

[andrewleech]

Ah drats, turns out that data being sent "out of order" isn't really a problem....
all my latest testing on the host side has been with python apps / repl using pyserial, on both windows and linux.

Turns out

https://github.com/pyserial/pyserial/blob/7aeea35429d15f3eefed10bbb659674638903e3a/serial/serialwin32.py#L84

https://github.com/pyserial/pyserial/blob/7aeea35429d15f3eefed10bbb659674638903e3a/serial/serialposix.py#L351

In its implementation for serial port opening, right after it self._reconfigure_port() (main contents of port opening) it performs a self._reset_input_buffer() which basically does exactly what it sounds like.

So that's where my "data sent slightly too early" is being thrown away.

On micropython, the stm port is using the STM usb stack, not TinyUSB. It has a feature where data "sent" to usb CDC at startup is buffered (in the usb stack), before USB is init / connected. Then when USB is connected, data previously buffered is flushed down the line to the client. This feature has been there for years and is quite popular, I really want to replicate this feature on TinyUSB.
It works fine on the same (python based) serial applications I've been trying to use for my current efforts.
There must be something in the STM implementation that's not flushing this data until slightly later, after the python serial port opening code has performed its own buffer reset.