[Usb Serial JTAG] [Deadlock] [Console Deinit] esp_vfs_usb_serial_jtag_use_nonblocking() causes deadlock (IDFGH-8520)

[chipweinberger]

Edit: Pull Request: #9983 now fixes this. This was due to linenoise thread forever holding the _readlock semaphore, which blocked esp_vfs_usb_serial_jtag_use_nonblocking().

v4.4.2
ESP32-S3

Steps to reproduce.

Related Issue: #9964

Goal: To deinit the Usb Serial JTAG Console if there has been no user input after 3 seconds since boot, because we otherwise need to use the port for USB Midi Host.

Unfortunately it deadlocks at _lock_acquire_recursive(&s_ctx.read_lock); in esp_vfs_usb_serial_jtag_use_nonblocking() . Hopefully I can explain it well.

Relevant code:
https://github.com/espressif/esp-idf/blob/master/components/vfs/vfs_usb_serial_jtag.c
https://github.com/espressif/esp-idf/blob/master/components/driver/usb_serial_jtag.c

I've debugged it pretty far.

1. I'm using USB Serial JTAG as the Console, via Menu Config
2. During boot I Initialize a linenoise console & thread, e.g. while(!should_stop) { char* line = linenoise(prompt); ....}
3. At this point, everything works fine. No problems. I can use the console.
4. The problems come when I try and deinit the console.
5. From the main task, I call code that looks like this, copied from esp_console_repl.c:

Deinit Code:

void pd_console_api_deinit(pd_error_t* error)
{
    pd_err_unset(error);

/*
    // I'VE YET FOUND A WAY TO ACHEIVE THIS!
    // wait for console thread to stop
    ESP_LOGI(TAG, "waiting for console thread to exit...");
    should_stop = true;
    while (!stopped) {
        // write empty line to stdin to unblock the console thread
        //write(0, " \r\n",4); 
        //write(1, " \r\n",4); 
        //fputc('\n', stdin);
        //ungetc('\n',stdin);
        delayMillis(500);
    }
*/

    ESP_LOGI(TAG, "console deinit"); 
    esp_err_t err = esp_console_deinit();
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "esp_console_deinit() %s", esp_err_to_name(err));
        return;
    }

#if CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG

    ESP_LOGI(TAG, "usb nonblocking");

    esp_vfs_usb_serial_jtag_use_nonblocking();  // THIS IS WHERE THE DEADLOCK HAPPENS

    ESP_LOGI(TAG, "usb driver uninstall");
    err = usb_serial_jtag_driver_uninstall();
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "usb_serial_jtag_driver_uninstall() %s", esp_err_to_name(err));
        return;
    }

#endif

    ESP_LOGI(TAG, "deinitialized");
    pd_err_success(error);
    return;
}

Going deeper, here is the code of the function that deadlocks:

esp_vfs_usb_serial_jtag_use_nonblocking

void esp_vfs_usb_serial_jtag_use_nonblocking(void)
{
    _lock_acquire_recursive(&s_ctx.read_lock); // DEADLOCK HAPPENS HERE!
    _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;
    _lock_release_recursive(&s_ctx.write_lock);
    _lock_release_recursive(&s_ctx.read_lock);
}

This deadlock is not surprising, because I believe s_ctx.read_lock is currently still held by the linenoise() call!

Call chain:

1. linenoise() calls fgetc() or similar
2. usb_serial_jtag_read // THIS FUNCTION ACQUIRES THE READ LOCK!
3. usb_serial_jtag_read_char()
4. s_ctx.rx_func(fd);
5. usbjtag_rx_char_via_driver() // THIS FUNCTION BLOCKS FOREVER WAITING FOR INPUT

You can see that usbjtag_rx_char_via_driver blocks forever, so the read lock is never given back!

static int usbjtag_rx_char_via_driver(int fd)
{
    uint8_t c;
    TickType_t timeout = s_ctx.non_blocking ? 0 : portMAX_DELAY;
    int n = usb_serial_jtag_read_bytes(&c, 1, timeout);
    if (n <= 0) {
        return NONE;
    }
    return c;
}

I've yet to find a solution.

My Code

void pd_console_api_deinit(pd_error_t* error)
{
    pd_err_unset(error);

#if CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG

    ESP_LOGI(TAG, "usb nonblocking");
    esp_vfs_usb_serial_jtag_use_nonblocking();

#endif

    // wait for console thread to stop
    ESP_LOGI(TAG, "waiting for console thread to exit...");
    should_stop = true;
    while (!stopped) {
        // write empty line to stdin to unblock the console thread
        //write(0, " \r\n",4); 
        //write(1, " \r\n",4); 
        //fputc('\n', stdin);
        //ungetc('\n',stdin);
        delayMillis(500);
    }

    ESP_LOGI(TAG, "console deinit"); 
    esp_err_t err = esp_console_deinit();
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "esp_console_deinit() %s", esp_err_to_name(err));
        return;
    }

#if CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG

    ESP_LOGI(TAG, "usb nonblocking");
    esp_vfs_usb_serial_jtag_use_nonblocking();

    ESP_LOGI(TAG, "usb driver uninstall");
    err = usb_serial_jtag_driver_uninstall();
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "usb_serial_jtag_driver_uninstall() %s", esp_err_to_name(err));
        return;
    }

#elif CONFIG_ESP_CONSOLE_UART

    ESP_LOGI(TAG, "uart nonblocking");
    esp_vfs_dev_uart_use_nonblocking(CONSOLE_UART_NUM);

    ESP_LOGI(TAG, "uart driver uninstall");
    err = uart_driver_delete(CONSOLE_UART_NUM);
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "uart_driver_delete() %s", esp_err_to_name(err));
        return;
    }
#endif

    ESP_LOGI(TAG, "deinitialized");
    pd_err_success(error);
    return;
}

void init_uart_console(pd_error_t* error)
{
    pd_err_unset(error);

#if CONFIG_ESP_CONSOLE_UART

    ESP_LOGI(TAG, "init uart console");

    esp_err_t err;

    // Minicom, screen, idf_monitor send CR when ENTER key is pressed
    int rv = esp_vfs_dev_uart_port_set_rx_line_endings(CONSOLE_UART_NUM, ESP_LINE_ENDINGS_CR);
    if (rv != 0){
        pd_err_fail(error, TAG, "esp_vfs_dev_uart_port_set_rx_line_endings failed. errno: %i", errno);
        return;
    }

    // Move the caret to the beginning of the next line on '\n' 
    rv = esp_vfs_dev_uart_port_set_tx_line_endings(CONSOLE_UART_NUM, ESP_LINE_ENDINGS_CRLF);
    if (rv != 0){
        pd_err_fail(error, TAG, "esp_vfs_dev_uart_port_set_tx_line_endings failed. errno: %i", errno);
        return;
    }

    // Configure UART. Note that REF_TICK is used so that the baud rate remains
    // correct while APB frequency is changing in light sleep mode.
    const uart_config_t uart_config = {
            .baud_rate = 115200,
            .data_bits = UART_DATA_8_BITS,
            .parity = UART_PARITY_DISABLE,
            .stop_bits = UART_STOP_BITS_1,
            .flow_ctrl = UART_HW_FLOWCTRL_DISABLE,
            .rx_flow_ctrl_thresh = 0,
#ifdef CONFIG_IDF_TARGET_ESP32S3
            .source_clk = UART_SCLK_XTAL,
#else 
            .source_clk = UART_SCLK_APB,
#endif
    };

    // Set UART pins(TX: IO4, RX: IO5, RTS: IO18, CTS: IO19)
    err = uart_set_pin(CONSOLE_UART_NUM, 
        pd_gpio_get(PD_GPIO_UART_TX), // tx
        pd_gpio_get(PD_GPIO_UART_RX), // rx
        UART_PIN_NO_CHANGE, //rts
        UART_PIN_NO_CHANGE); //cts
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "uart_set_pin failed. %s", esp_err_to_name(err));
        return;
    }

    // Install UART driver for interrupt-driven reads and writes
    err = uart_driver_install(CONSOLE_UART_NUM, 256, 0, 0, NULL, 0);
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "uart_driver_install failed. %s", esp_err_to_name(err));
        return;
    }

    err = uart_param_config(CONSOLE_UART_NUM, &uart_config);
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "uart_param_config failed. %s", esp_err_to_name(err));
        return;
    }

    // Tell VFS to use UART driver
    esp_vfs_dev_uart_use_driver(CONSOLE_UART_NUM);
#endif
    pd_err_success(error);
}

void init_usb_serial_jtag_console(pd_error_t* error)
{
    pd_err_unset(error);

    ESP_LOGI(TAG, "init usb serial jtag console");

#if CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG

    esp_err_t err;

    // Disable buffering on stdin
    int rv = setvbuf(stdin, NULL, _IONBF, 0);
    if (rv != 0){
        pd_err_fail(error, TAG, "setvbuf(stdin, NULL, _IONBF, 0) failed. rv: %i", rv);
        return;
    }

    // Minicom, screen, idf_monitor send CR when ENTER key is pressed
    esp_vfs_dev_usb_serial_jtag_set_rx_line_endings(ESP_LINE_ENDINGS_CR);

    // Move the caret to the beginning of the next line on '\n'
    esp_vfs_dev_usb_serial_jtag_set_tx_line_endings(ESP_LINE_ENDINGS_CRLF);

    int fdOut = fileno(stdout);
    if (fdOut < 0){
        pd_err_fail(error, TAG, "fileno(stdout) failed. rv: %i", fdOut);
        return;
    }

    int fdIn = fileno(stdin);
    if (fdIn < 0){
        pd_err_fail(error, TAG, "fileno(stdin) failed. rv: %i", fdIn);
        return;
    }

    // Enable blocking mode on stdin and stdout
    rv = fcntl(fdOut, F_SETFL, 0);
    if (rv != 0){
        pd_err_fail(error, TAG, "fcntl(fdOut, F_SETFL, 0) failed. rv: %i", rv);
        return;
    }

    rv = fcntl(fdIn, F_SETFL, 0);
    if (rv != 0){
        pd_err_fail(error, TAG, "fcntl(fdIn, F_SETFL, 0) failed. rv: %i", rv);
        return;
    }

    usb_serial_jtag_driver_config_t config = {
        .tx_buffer_size = 1024,
        .rx_buffer_size = 1024
    };

    // Install USB-SERIAL-JTAG driver for interrupt-driven reads and writes
    err = usb_serial_jtag_driver_install(&config);
    if (err != ESP_OK) {
        pd_err_fail(error, TAG, "usb_serial_jtag_driver_install() failed. %s", esp_err_to_name(err));
        return;
    }

    // Tell vfs to use usb-serial-jtag driver
    esp_vfs_usb_serial_jtag_use_driver();

#endif
    pd_err_success(error);
    return;
}


void pd_console_api_init(pd_error_t* error)
{
    pd_err_unset(error);

    esp_err_t err;

    ESP_LOGI(TAG, "init");

    // clear these flags
    should_stop = false;
    stopped = false;

    // initialize error
    pd_error_t* sharedError = pd_console_shared_error();
    pd_err_init_alloc(sharedError);

    // Drain stdout before reconfiguring it
    pd_fflush(stdout, error);
    if (is_fail(*error)){
        return;
    }

    pd_fsync(fileno(stdout), error);
    if (is_fail(*error)){
        return;
    }

    // Disable buffering on stdin 
    pd_setvbuf(stdin, NULL, _IONBF, 0, error);
    if (is_fail(*error)){
        return;
    }

#if CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG
    init_usb_serial_jtag_console(error);
    if (is_fail(*error)){
        return;
    }
#else 
    init_uart_console(error);
    if (is_fail(*error)){
        return;
    }
#endif

    // Initialize the console
    esp_console_config_t console_config = {
            .max_cmdline_length = 256,
            .max_cmdline_args = 8,
            .hint_color = atoi(LOG_COLOR_CYAN),
            .hint_bold = 0,
    };
    err = esp_console_init(&console_config);
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "esp_console_init failed. %s", esp_err_to_name(err));
        return;
    }

    // remember success
    esp_console_init_success = true;

    // Configure linenoise line completion library 
    // Enable multiline editing. If not set, long commands will scroll within a single line. 
    linenoiseSetMultiLine(1);

    // Tell linenoise where to get command completions and hints 
    linenoiseSetCompletionCallback(&esp_console_get_completion);
    linenoiseSetHintsCallback((linenoiseHintsCallback*) &esp_console_get_hint);

    // Set command history size
    linenoiseHistorySetMaxLen(100);

    // Set command maximum length
#ifdef ESP_IDF4v4
    linenoiseSetMaxLineLen(console_config.max_cmdline_length);
#endif

    // Don't return empty lines
    linenoiseAllowEmpty(true);

    err = esp_console_register_help_command();
    if (err != ESP_OK){
        pd_err_fail(error, TAG, "esp_console_register_help_command failed. %s", esp_err_to_name(err));
        return;
    }

    //
    // Register All Commands
    //

    uint32_t count = pd_api_registry_count();
    pd_registered_api_t* apiList = pd_api_registry_list();

    ESP_LOGI(TAG, "registering %u uris", count);

    for (int i = 0; i < count; i++){

        pd_registered_api_t api = apiList[i];

        pd_console_register_cmd(api.uri, api.sig, error);

        if (is_fail(*error)) {
            pd_err_fail(error, TAG, "failed to register %s", api.uri);
            return;
        }

        // 
        // also, register a convenience API uri
        // that is just a number
        //

        // Note: we never deallocate this on purpose. it lives forever.
        char* apiIdxStr = (char*) malloc_safe(4, HERE);
        snprintf(apiIdxStr, 4, "%u", i);

        pd_console_register_cmd((const char*) apiIdxStr, api.sig, error);

        if (is_fail(*error)) {
            pd_err_fail(error, TAG, "failed to register %s", api.uri);
            return;
        }
    }

    pd_err_success(error);
    return;
}

uint32_t pd_console_api_executed_cmds_count() {
    return executedCmdsCount;
}

void pd_console_api_create_task(pd_error_t* error)
{
    pd_err_unset(error);

    ESP_LOGI(TAG, "xTaskCreate console");

    TaskHandle_t xTaskConsole;

    // Create a task to send midi msgs
    bool success = xTaskCreate(pd_console_api_enter_loop, "console",
                                               8*1024, // stack size
                                               (void *) 0, // argument 
                                               PD_PRIORITY_CONSOLE_API_TASK,
                                               &xTaskConsole);
    if (!success) {
        pd_err_fail(error, TAG, "xTaskCreate() console failed.");
        return;
    }

    pd_err_success(error);
}

void pd_console_api_enter_loop(void* arg)
{
    ESP_LOGI(TAG, "console task start");

    if (!esp_console_init_success){
        ESP_LOGE(TAG, "enter loop: console is not initialized");
        return;
    }

    // Prompt to be printed before each line.
    // This can be customized, made dynamic, etc.
    const char* prompt = LOG_COLOR(LOG_COLOR_BLUE) "jmx-console> " LOG_RESET_COLOR;

    printf2("=== Console Started ===\n" \
           "Type 'help' - get the list of commands.\n" \
           "UP/DOWN - navigate command history.\n" \
           "TAB - auto-complete.\n");

    // Figure out if the terminal supports escape sequences
    int probe_status = linenoiseProbe();
    if (probe_status) { 

        printf2("Your terminal application does not support escape sequences.\n"
               "Line editing and history features are disabled.\n");

        linenoiseSetDumbMode(1);

        // Since the terminal doesn't support escape sequences,
        // don't use color codes in the prompt.
        prompt = "jmx-console> ";
    }

    linenoiseSetDumbMode(1);

    while(!should_stop) {

        PD_LOGV(TAG, "iterate loop");

        // Get a line using linenoise.
        // The line is returned when ENTER is pressed.
        char* line = linenoise(prompt);
        if (line == NULL) { // Ignore empty lines
            continue;
        }

        executedCmdsCount++;

        // Add the command to the history 
        linenoiseHistoryAdd(line);

        //
        // which cmd we are executing?
        //

        // clear
        memset(cmdName, 0, sizeof(cmdName));

        // commands with arguments?
        if (strstr(line, " ")) {
            char* space = strstr(line, " ");
            memcpy(cmdName, line, PDMIN(space - line, sizeof(cmdName) - 1));
        } else {
            // commands without arguments
            strncpy2(cmdName, line, sizeof(cmdName));
        }

        // Is the cmdName a number?
        // If so, convert it to it's actual uri
        if (isUInteger64(cmdName)) {
            int apiIdx = atoi(cmdName);
            if(apiIdx >= 0 && apiIdx < pd_api_registry_count()){
                pd_registered_api_t* apiList = pd_api_registry_list();
                pd_registered_api_t api = apiList[apiIdx];
                memcpy(cmdName, api.uri, strbuflen(api.uri));
            }
        }

        // Try to run the command 
        int ret;
        esp_err_t err = esp_console_run(line, &ret);
        if (err == ESP_ERR_NOT_FOUND) {

            printf2("Console: Unrecognized command: %s\n", cmdName);

        } else if (err == ESP_ERR_INVALID_ARG) {

            // command was empty
            printf2("Console: Empty command\n");

        } else if (err == ESP_OK && ret != ESP_OK) {

            printf2("Console: Command returned non-zero error code: 0x%x (%s)\n",
                ret, esp_err_to_name(ret));

        } else if (err != ESP_OK) {

            printf2("Console: Internal error: %s\n", esp_err_to_name(err));
        }

        // linenoise allocates line buffer on the 
        // heap, so need to free it
        linenoiseFree(line);
    }

    stopped = true;
    ESP_LOGI(TAG, "console task exit");
    vTaskDelete(NULL);
}

[chipweinberger]

@igrr

[chipweinberger]

My console Init code is copied from esp_console_new_repl_usb_serial_jtag, so just like that code I am also calling:

    /* Enable non-blocking mode on stdin and stdout */
    fcntl(fileno(stdout), F_SETFL, 0);
    fcntl(fileno(stdin), F_SETFL, 0);

But the comment confuses me. Shouldn't it be this code?

    fcntl(fileno(stdout), F_SETFL, O_NONBLOCK);
    fcntl(fileno(stdin), F_SETFL, O_NONBLOCK);

But regardless, it does not fix the issue. I still deadlock at the same place.

edit: i think this is because linenoiseProbe() doesnt restore the O_NONBLOCK flag correctly

    /* Restore old mode */
    flags &= ~O_NONBLOCK; // chip weinberger: this will always set O_NONBLOCK bit to zero
    res = fcntl(stdin_fileno, F_SETFL, flags);

[chipweinberger]

I've tried replacing esp_vfs_usb_serial_jtag_use_driver() with esp_vfs_usb_serial_jtag_use_nonblocking(), but 3 things happend.

1. the original hang was fixed. It used to hang at a seemingly random place (during bluetooth init), but now it got much further
2. the device still hung (or crashed? rst:0xc (RTC_SW_CPU_RST)) at usb_host_install() when switching into usb host mode.
3. It caused linenoise to continually read some funky data. see below.

Logs:

Console: Unrecognized command: xV[
Console: Usb Console Enabled
Console: Unrecognized command: xVYI
Console: Unrecognized command: xVYI
Console: Unrecognized command: xVYI
Console: Unrecognized command: xVYI
Console: Unrecognized command: xVYI

I'm having a hard time trusting USB Serial JTAG.... 😔 It's quite hard to use without issues.

The UART console works so easily, but Usb Serial JTAG is much more tricky, especially if you want to dynamically switch between console and Usb Host.

Why dynamically switch? Under normal operation I need to use USB Host, but retaining access to the USB Serial Console when needed is extremely useful.

[chipweinberger]

Futhermore, from the docs:

https://docs.espressif.com/projects/esp-idf/en/latest/esp32s3/api-guides/usb-serial-jtag-console.html

An USB-to-serial bridge chip will just send the bytes to a (not listening) chip, while the USB Serial/JTAG Controller will block until the application reads the bytes. This can lead to a non-responsive looking terminal program.

I really think this should not be the default behavior. It is incredibly hard to debug a hanging program. It is greatly preferable to skip the bytes if the buffer is full. I am currently debugging with nothing attached to the USB port, so it should never hang I would think, but for some reason using esp_vfs_usb_serial_jtag_use_driver() still causes my device to freeze (not sure why). This is very difficult to debug. I thought esp_vfs_usb_serial_jtag_use_nonblocking() would fix it, and while it did fix the hang, the xVYI problem replaced it.

[chipweinberger]

I'm working on a ESP-IDF solution that uses new functions:

esp_err_t usb_serial_jtag_unblock_reads();
void esp_vfs_usb_serial_jtag_use_driver_for_rx(void);
void vRingbufferUnblock(RingbufHandle_t xRingbuffer);

[chipweinberger]

Pull Request: #9983

Please consider & feel free to modify. It has been tested on S3.