fix(usb-serial-jtag): Call driver-specific fsync function for usb-serial-jtag

The VFS driver used to switch to the interrupt-driven driver for rx and tx functions, but
still called its own fsync function, which poked the hardware directly. This interfered
with the driver interrupt, causing spurious bytes to disappear. This adds a driver-specific
sync function and support for that in the vfs layer.

Closes https://github.com/espressif/esp-idf/issues/13939

components/esp_driver_usb_serial_jtag/include/driver/usb_serial_jtag.h

@@ -74,6 +74,15 @@ int usb_serial_jtag_read_bytes(void* buf, uint32_t length, TickType_t ticks_to_w
  */
 int usb_serial_jtag_write_bytes(const void* src, size_t size, TickType_t ticks_to_wait);
 
+/**
+ * @brief Blocks until all data written using `usb_serial_jtag_write_bytes` is sent to the host, or until timeout.
+ *
+ * @param ticks_to_wait Maximum timeout in RTOS ticks
+ *
+ * @return ESP_OK when flushed, ESP_ERR_TIMEOUT on timeout.
+ */
+esp_err_t usb_serial_jtag_wait_tx_done(TickType_t ticks_to_wait);
+
 /**
  * @brief Uninstall USB-SERIAL-JTAG driver.
  *

components/esp_driver_usb_serial_jtag/src/usb_serial_jtag.c

@@ -44,7 +44,11 @@ typedef struct {
     // TX parameters
     RingbufHandle_t tx_ring_buf;        /*!< TX ring buffer handler */
     uint8_t tx_stash_buf[USB_SER_JTAG_ENDP_SIZE];  /*!< Data buffer to stash TX FIFO data */
-    size_t tx_stash_cnt;                          /*!< Number of stashed TX FIFO bytes */
+    size_t tx_stash_cnt;                           /*!< Number of stashed TX FIFO bytes */
+
+    //Synchronization stuff, only used for flush for now
+    SemaphoreHandle_t tx_mux;
+    SemaphoreHandle_t tx_idle_sem;
 } usb_serial_jtag_obj_t;
 
 static usb_serial_jtag_obj_t *p_usb_serial_jtag_obj = NULL;
@@ -111,6 +115,19 @@ static void usb_serial_jtag_isr_handler_default(void *arg)
                 // We will also disable the interrupt as for now there's no need to handle the
                 // TX interrupt again. We'll re-enable this externally if we need data sent.
                 usb_serial_jtag_ll_disable_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
+
+                // Technically something could have been pushed into the ringbuffer between us checking
+                // here and us disabling the interrupt. That would mean that data would not be
+                // transmitted anymore. Check for that case.
+                UBaseType_t bytes_waiting;
+                vRingbufferGetInfo(p_usb_serial_jtag_obj->tx_ring_buf, NULL, NULL, NULL, NULL, &bytes_waiting);
+                if (bytes_waiting) {
+                    // Uh-oh, it happened. Re-enable interrupts so we can process the data the next run.
+                    usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
+                } else {
+                    //Nope, still nothing. Mark tx as idle.
+                    xSemaphoreGiveFromISR(p_usb_serial_jtag_obj->tx_idle_sem, &xTaskWoken);
+                }
             }
         }
     }
@@ -159,6 +176,20 @@ esp_err_t usb_serial_jtag_driver_install(usb_serial_jtag_driver_config_t *usb_se
         goto _exit;
     }
 
+    p_usb_serial_jtag_obj->tx_mux = xSemaphoreCreateMutex();
+    if (p_usb_serial_jtag_obj->tx_mux == NULL) {
+        ESP_LOGE(USB_SERIAL_JTAG_TAG, "tx_mux create error");
+        err = ESP_ERR_NO_MEM;
+        goto _exit;
+    }
+
+    p_usb_serial_jtag_obj->tx_idle_sem = xSemaphoreCreateBinary();
+    if (p_usb_serial_jtag_obj->tx_idle_sem == NULL) {
+        ESP_LOGE(USB_SERIAL_JTAG_TAG, "tx_idle_sem create error");
+        err = ESP_ERR_NO_MEM;
+        goto _exit;
+    }
+
     // Enable USB-Serial-JTAG peripheral module clock
     USJ_RCC_ATOMIC() {
         usb_serial_jtag_ll_enable_bus_clock(true);
@@ -181,6 +212,9 @@ esp_err_t usb_serial_jtag_driver_install(usb_serial_jtag_driver_config_t *usb_se
     // have anything to send.
     usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_OUT_RECV_PKT);
 
+    //Assume tx is idle; if any we have nothing in the ringbuffer so this is probably true.
+    xSemaphoreGive(p_usb_serial_jtag_obj->tx_idle_sem);
+
     err = esp_intr_alloc(ETS_USB_SERIAL_JTAG_INTR_SOURCE, 0, usb_serial_jtag_isr_handler_default, NULL, &p_usb_serial_jtag_obj->intr_handle);
     if (err != ESP_OK) {
         goto _exit;
@@ -221,14 +255,56 @@ int usb_serial_jtag_write_bytes(const void* src, size_t size, TickType_t ticks_t
     ESP_RETURN_ON_FALSE(src != NULL, ESP_ERR_INVALID_ARG, USB_SERIAL_JTAG_TAG, "Invalid buffer pointer.");
     ESP_RETURN_ON_FALSE(p_usb_serial_jtag_obj != NULL, ESP_ERR_INVALID_ARG, USB_SERIAL_JTAG_TAG, "The driver hasn't been initialized");
 
-    BaseType_t result = pdTRUE;
+    //This will block when something else is waiting in wait_tx_done, making sure we don't add data to the ringbuffer.
+    //Note that the ringbuffer itself is thread-safe, so this is only needed to handle wait_tx_done.
+    BaseType_t result = xSemaphoreTake(p_usb_serial_jtag_obj->tx_mux, ticks_to_wait);
+    if (result == pdFALSE) {
+        return 0;
+    }
+
+    //Mark TX as not idle so flush function knows to wait. Note we don't care if it was already not idle, so no
+    //timeout and we don't check if this succeeds; we just want to make sure the semaphore is taken.
+    xSemaphoreTake(p_usb_serial_jtag_obj->tx_idle_sem, 0);
+
     result = xRingbufferSend(p_usb_serial_jtag_obj->tx_ring_buf, (void*)src, size, ticks_to_wait);
     // Re-enable the TX interrupt. If this was disabled, this will immediately trigger the ISR
-    // and send the things we just put in the ringbuffer.
+    // and send the things we just put in the ringbuffer. Note that even though this is a
+    // read-modify-write operation on the interrupt enable register that could happen at the
+    // same point the ISR does a read-modify-write to disable the interrupt,
     usb_serial_jtag_ll_ena_intr_mask(USB_SERIAL_JTAG_INTR_SERIAL_IN_EMPTY);
+    xSemaphoreGive(p_usb_serial_jtag_obj->tx_mux);
     return (result == pdFALSE) ? 0 : size;
 }
 
+esp_err_t usb_serial_jtag_wait_tx_done(TickType_t ticks_to_wait)
+{
+    int r;
+    TimeOut_t timeout;
+    vTaskSetTimeOutState(&timeout);
+    // Make sure write_bytes blocks so nothing is added to the ringbuffer.
+    // Note that this can time out (e.g. blocked ringbuffer while writing)
+    r = xSemaphoreTake(p_usb_serial_jtag_obj->tx_mux, ticks_to_wait);
+    if (r) {
+        // Adjust timeout to compensate for the time we waited for tx_mux. Note xTaskCheckForTimeOut
+        // changes ticks_to_wait accordingly.
+        if (xTaskCheckForTimeOut(&timeout, &ticks_to_wait)) {
+            // if this triggers, we timed out: we got tx_mux at the exact time of the timeout? Probably
+            // never happens, but handle correctly anyway.
+            ticks_to_wait = 0;
+        }
+        // Check if we're idle or wait until we are (or time out)
+        r = xSemaphoreTake(p_usb_serial_jtag_obj->tx_idle_sem, ticks_to_wait);
+        if (r) {
+            // We could take the semaphore, meaning tx is done now. Immediately give it again so
+            // the next run of usb_serial_jtag_wait_tx_done also succeeds.
+            xSemaphoreGive(p_usb_serial_jtag_obj->tx_idle_sem);
+        }
+        // Re-allow writes.
+        xSemaphoreGive(p_usb_serial_jtag_obj->tx_mux);
+    }
+    return r ? ESP_OK : ESP_ERR_TIMEOUT;
+}
+
 //Note that this is also called when usb_serial_jtag_driver_install errors out and as such should
 //work on a half-initialized driver as well.
 esp_err_t usb_serial_jtag_driver_uninstall(void)
@@ -253,6 +329,14 @@ esp_err_t usb_serial_jtag_driver_uninstall(void)
         vRingbufferDelete(p_usb_serial_jtag_obj->tx_ring_buf);
         p_usb_serial_jtag_obj->tx_ring_buf = NULL;
     }
+    if (p_usb_serial_jtag_obj->tx_idle_sem) {
+        vSemaphoreDelete(p_usb_serial_jtag_obj->tx_idle_sem);
+        p_usb_serial_jtag_obj->tx_idle_sem  = NULL;
+    }
+    if (p_usb_serial_jtag_obj->tx_mux) {
+        vSemaphoreDelete(p_usb_serial_jtag_obj->tx_mux);
+        p_usb_serial_jtag_obj->tx_mux  = NULL;
+    }
     heap_caps_free(p_usb_serial_jtag_obj);
     p_usb_serial_jtag_obj = NULL;
     return ESP_OK;

components/esp_driver_usb_serial_jtag/src/usb_serial_jtag_vfs.c

@@ -50,10 +50,13 @@
 typedef void (*tx_func_t)(int, int);
 // read bytes function type
 typedef int (*rx_func_t)(int);
+// fsync bytes function type
+typedef int (*fsync_func_t)(int);
 
-// Basic functions for sending and receiving bytes
-static void usb_serial_jtag_tx_char(int fd, int c);
-static int usb_serial_jtag_rx_char(int fd);
+// Basic functions for sending and receiving bytes and fsync
+static void usb_serial_jtag_tx_char_no_driver(int fd, int c);
+static int usb_serial_jtag_rx_char_no_driver(int fd);
+static int usb_serial_jtag_wait_tx_done_no_driver(int fd);
 
 //If no host is listening to the CDCACM port, the TX buffer
 //will never be able to flush to the host. Instead of the Tx
@@ -84,10 +87,12 @@ typedef struct {
     esp_line_endings_t tx_mode;
     // Newline conversion mode when receiving
     esp_line_endings_t rx_mode;
-    // Functions used to write bytes to port. Default to "basic" functions.
+    // Function used to write bytes to port. Default to "basic" functions.
     tx_func_t tx_func;
-    // Functions used to read bytes from port. Default to "basic" functions.
+    // Function used to read bytes from port. Default to "basic" functions.
     rx_func_t rx_func;
+    // Function used to make sure all data is sent to the host.
+    fsync_func_t fsync_func;
     // Timestamp of last time we managed to write something to the tx buffer
     int64_t last_tx_ts;
 } usb_serial_jtag_vfs_context_t;
@@ -98,8 +103,9 @@ static usb_serial_jtag_vfs_context_t s_ctx = {
     .peek_char = NONE,
     .tx_mode = DEFAULT_TX_MODE,
     .rx_mode = DEFAULT_RX_MODE,
-    .tx_func = usb_serial_jtag_tx_char,
-    .rx_func = usb_serial_jtag_rx_char
+    .tx_func = usb_serial_jtag_tx_char_no_driver,
+    .rx_func = usb_serial_jtag_rx_char_no_driver,
+    .fsync_func = usb_serial_jtag_wait_tx_done_no_driver
 };
 
 static int usb_serial_jtag_open(const char * path, int flags, int mode)
@@ -108,7 +114,7 @@ static int usb_serial_jtag_open(const char * path, int flags, int mode)
     return 0;
 }
 
-static void usb_serial_jtag_tx_char(int fd, int c)
+static void usb_serial_jtag_tx_char_no_driver(int fd, int c)
 {
     uint8_t cc = (uint8_t)c;
     // Try to write to the buffer as long as we still expect the buffer to have
@@ -133,7 +139,7 @@ static void usb_serial_jtag_tx_char(int fd, int c)
 
 }
 
-static int usb_serial_jtag_rx_char(int fd)
+static int usb_serial_jtag_rx_char_no_driver(int fd)
 {
     uint8_t c;
     int l = usb_serial_jtag_ll_read_rxfifo(&c, 1);
@@ -262,9 +268,8 @@ static int usb_serial_jtag_fcntl(int fd, int cmd, int arg)
     return result;
 }
 
-static int usb_serial_jtag_fsync(int fd)
+static int usb_serial_jtag_wait_tx_done_no_driver(int fd)
 {
-    _lock_acquire_recursive(&s_ctx.write_lock);
     usb_serial_jtag_ll_txfifo_flush();
     //Wait for the host to have picked up the buffer, but honour the timeout in
     //case the host is not listening.
@@ -275,11 +280,24 @@ static int usb_serial_jtag_fsync(int fd)
             //send a 0-byte packet to indicate the end of the USB transfer, otherwise
             //those 64 bytes will get stuck in the hosts buffer.
             usb_serial_jtag_ll_txfifo_flush();
-            break;
+            return 0;
         }
     }
+    //Timeout. Host probably isn't listening.
+    return EIO;
+}
+
+static int usb_serial_jtag_fsync(int fd)
+{
+    _lock_acquire_recursive(&s_ctx.write_lock);
+    int r = s_ctx.fsync_func(fd);
     _lock_release_recursive(&s_ctx.write_lock);
-    return 0;
+    if (r == 0) {
+        return 0;
+    } else {
+        errno = r;
+        return -1;
+    }
 }
 
 #ifdef CONFIG_VFS_SUPPORT_TERMIOS
@@ -442,12 +460,20 @@ static void usbjtag_tx_char_via_driver(int fd, int c)
     }
 }
 
+static int usbjtag_wait_tx_done_via_driver(int fd)
+{
+    TickType_t ticks = (TX_FLUSH_TIMEOUT_US / 1000) / portTICK_PERIOD_MS;
+    esp_err_t r = usb_serial_jtag_wait_tx_done(ticks);
+    return (r == ESP_OK) ? 0 : EIO;
+}
+
 void usb_serial_jtag_vfs_use_nonblocking(void)
 {
     _lock_acquire_recursive(&s_ctx.read_lock);
     _lock_acquire_recursive(&s_ctx.write_lock);
-    s_ctx.tx_func = usb_serial_jtag_tx_char;
-    s_ctx.rx_func = usb_serial_jtag_rx_char;
+    s_ctx.tx_func = usb_serial_jtag_tx_char_no_driver;
+    s_ctx.rx_func = usb_serial_jtag_rx_char_no_driver;
+    s_ctx.fsync_func = usb_serial_jtag_wait_tx_done_no_driver;
     _lock_release_recursive(&s_ctx.write_lock);
     _lock_release_recursive(&s_ctx.read_lock);
 }
@@ -458,6 +484,7 @@ void usb_serial_jtag_vfs_use_driver(void)
     _lock_acquire_recursive(&s_ctx.write_lock);
     s_ctx.tx_func = usbjtag_tx_char_via_driver;
     s_ctx.rx_func = usbjtag_rx_char_via_driver;
+    s_ctx.fsync_func = usbjtag_wait_tx_done_via_driver;
     _lock_release_recursive(&s_ctx.write_lock);
     _lock_release_recursive(&s_ctx.read_lock);
 }

components/esp_driver_usb_serial_jtag/test_apps/usb_serial_jtag/main/CMakeLists.txt

@@ -2,6 +2,6 @@
 # the component can be registered as WHOLE_ARCHIVE
 idf_component_register(
     SRCS "test_app_main.c" "test_usb_serial_jtag.c"
-    REQUIRES driver unity vfs
+    REQUIRES driver unity vfs esp_timer
     WHOLE_ARCHIVE
 )

components/esp_driver_usb_serial_jtag/test_apps/usb_serial_jtag/main/test_usb_serial_jtag.c

@@ -10,6 +10,7 @@
 #include "driver/usb_serial_jtag.h"
 #include "esp_log.h"
 #include "esp_vfs_dev.h"
+#include "esp_timer.h"
 #include "driver/usb_serial_jtag_vfs.h"
 #include "driver/usb_serial_jtag.h"
 #include <freertos/FreeRTOS.h>
@@ -63,3 +64,59 @@ TEST_CASE("test print via usb_serial_jtag driver multiple times in different tas
     usb_serial_jtag_vfs_use_nonblocking();
     usb_serial_jtag_driver_uninstall();
 }
+
+/*
+It's hard to properly test if fsync() is working as there's not really a way to see if there's still
+data dribbling out to the host if it is not. We can use some heuristics, though: fsync() should be
+pretty fast when there's no data sent in a while, while it is slower when the USB-JTAG-serial device
+still is sending out data. Big issues like e.g. a timeout in the fsync logic, or the fsync logic not
+syncing up at all, should be easy to detect like this.
+*/
+#define FSYNC_DATA_SZ 4096
+
+TEST_CASE("see if fsync appears to work", "[usb_serial_jtag]")
+{
+    usb_serial_jtag_driver_config_t cfg = {
+        .tx_buffer_size = FSYNC_DATA_SZ,
+        .rx_buffer_size = 128
+    };
+
+    TEST_ESP_OK(usb_serial_jtag_driver_install(&cfg));
+
+    // Tell vfs to use usb-serial-jtag driver
+    usb_serial_jtag_vfs_use_driver();
+
+    char *buf = malloc(FSYNC_DATA_SZ);
+    //fill with NULL bytes as they won't be printed to the terminal but will be sent over USB
+    memset(buf, 0, FSYNC_DATA_SZ);
+
+    //make sure caches are warmed up by doing some dummy stuff
+    uint64_t start_us = esp_timer_get_time();
+    fsync(0);
+    uint64_t end_us = esp_timer_get_time();
+    usb_serial_jtag_write_bytes(buf, FSYNC_DATA_SZ, 1);
+
+    vTaskDelay(pdMS_TO_TICKS(200));
+
+    //Measure with USB-serial-JTAG idle
+    start_us = esp_timer_get_time();
+    fsync(0);
+    end_us = esp_timer_get_time();
+    printf("No data in queue: %d us\n", (int)(end_us - start_us));
+    TEST_ASSERT_LESS_THAN_INT(100, end_us - start_us);
+
+    vTaskDelay(pdMS_TO_TICKS(200));
+
+    //Measure with USB-serial-JTAG active
+    usb_serial_jtag_write_bytes(buf, FSYNC_DATA_SZ, portMAX_DELAY);
+    start_us = esp_timer_get_time();
+    fsync(0);
+    end_us = esp_timer_get_time();
+    printf("With data in queue: %d us\n", (int)(end_us - start_us));
+    TEST_ASSERT_GREATER_THAN_INT(1000, end_us - start_us);
+    TEST_ASSERT_LESS_THAN_INT(45000, end_us - start_us); //50ms means fsync hit a timeout
+
+    free(buf);
+    usb_serial_jtag_vfs_use_nonblocking();
+    usb_serial_jtag_driver_uninstall();
+}

components/esp_driver_usb_serial_jtag/test_apps/usb_serial_jtag/pytest_usb_serial_jtag.py

@@ -21,3 +21,7 @@ def test_usb_serial_jtag_dev(dut: Dut) -> None:                # type: ignore
     dut.write('\"test print via usb_serial_jtag driver multiple times in different tasks\"')
     for i in range(300 * 2):
         dut.expect(r'Oh, hello world (\d), this test is for testing message and parse in python, time (\d+)', timeout=10)
+    dut.expect('PASS')
+    dut.expect_exact('Enter next test, or \'enter\' to see menu')
+    dut.write('\"see if fsync appears to work\"')
+    dut.expect('PASS')