Merge branch 'fix/char_skip_using_usj_proper_fix' into 'master'

fix(usb-serial-jtag): Call driver-specific fsync function for usb-serial-jtag rather than poking the hardware directly

Closes IDFGH-12988

See merge request espressif/esp-idf!32473

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')