espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.84k stars 7.32k forks source link

Calling ESP_LOGI from a critical section of a task function (IDFGH-5076) #6860

Closed norventa closed 3 years ago

norventa commented 3 years ago

Environment

Problem Description

// From a task function:

portMUX_TYPE mutex = portMUX_INITIALIZER_UNLOCKED;

void taskfn(void *) { do { portENTER_CRITICAL(&mutex); ESP_LOGI("test", "Hello"); portEXIT_CRITICAL(&mutex); } while (1); }

Expected Behavior

Output log.

Actual Behavior

locks.c throws a wobbly (look for HERE in code below):

When xPortCanYield() is called it is used to determine if in an interrupt context or in a task context. It mistakenly believes it to be an interrupt context.

// From locks.c
/* Acquire the mutex semaphore for lock. wait up to delay ticks.
   mutex_type is queueQUEUE_TYPE_RECURSIVE_MUTEX or queueQUEUE_TYPE_MUTEX
*/
static int IRAM_ATTR lock_acquire_generic(_lock_t *lock, uint32_t delay, uint8_t mutex_type) {
    xSemaphoreHandle h = (xSemaphoreHandle)(*lock);
    if (!h) {
        if (xTaskGetSchedulerState() == taskSCHEDULER_NOT_STARTED) {
            return 0; /* locking is a no-op before scheduler is up, so this "succeeds" */
        }
        /* lazy initialise lock - might have had a static initializer in newlib (that we don't use),
           or _lock_init might have been called before the scheduler was running... */
        lock_init_generic(lock, mutex_type);
        h = (xSemaphoreHandle)(*lock);
        configASSERT(h != NULL);
    }

    BaseType_t success;
    if (!xPortCanYield()) {
        /* In ISR Context */
        if (mutex_type == queueQUEUE_TYPE_RECURSIVE_MUTEX) {

// HERE
            abort(); /* recursive mutexes make no sense in ISR context */

        }
        BaseType_t higher_task_woken = false;
        success = xSemaphoreTakeFromISR(h, &higher_task_woken);
        if (!success && delay > 0) {
            abort(); /* Tried to block on mutex from ISR, couldn't... rewrite your program to avoid libc interactions in ISRs! */
        }
        if (higher_task_woken) {
            portYIELD_FROM_ISR();
        }
    }
    else {
        /* In task context */
        if (mutex_type == queueQUEUE_TYPE_RECURSIVE_MUTEX) {
            success = xSemaphoreTakeRecursive(h, delay);
        } else {
            success = xSemaphoreTake(h, delay);
        }
    }

    return (success == pdTRUE) ? 0 : -1;
}

Debug Logs

0 0x40086377:0x3ffd07e0 in panic_abort at C:\Users\Dougi.platformio\packages\framework-espidf\components\esp_system/panic.c:330

1 0x40086a15:0x3ffd0800 in esp_system_abort at C:\Users\Dougi.platformio\packages\framework-espidf\components\esp_system/system_api.c:106

2 0x4008a1fa:0x3ffd0820 in abort at C:\Users\Dougi.platformio\packages\framework-espidf\components\newlib/abort.c:46

3 0x400835b6:0x3ffd0890 in lock_acquire_generic at C:\Users\Dougi.platformio\packages\framework-espidf\components\newlib/locks.c:142

4 0x400836d9:0x3ffd08c0 in _lock_acquire_recursive at C:\Users\Dougi.platformio\packages\framework-espidf\components\newlib/locks.c:170

5 0x400f1e96:0x3ffd08e0 in _vfprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:853 (discriminator 2)

6 0x400f4ed5:0x3ffd0bf0 in vprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vprintf.c:34 (discriminator 5)

7 0x400fcfc1:0x3ffd0c20 in esp_log_writev at C:\Users\Dougi.platformio\packages\framework-espidf\components\log/log.c:189

8 0x4008a08d:0x3ffd0c50 in esp_log_write at C:\Users\Dougi.platformio\packages\framework-espidf\components\log/log.c:199

9 0x400d61fe:0x3ffd0ca0 in setPower(unsigned int, double, unsigned int) at src/Program.cpp:259

10 0x400d62c5:0x3ffd0da0 in doRateStep(DFiringStep const&, unsigned int) at src/Program.cpp:302

11 0x400d6504:0x3ffd0dd0 in doRun() at src/Program.cpp:418

12 0x400d65af:0x3ffd0e20 in TaskFn(void*) at src/Program.cpp:470

13 0x40086a1d:0x3ffd0e40 in vPortTaskWrapper at C:\Users\Dougi.platformio\packages\framework-espidf\components\freertos\xtensa/port.c:143

Other items if possible

/ List of deprecated options /

define CONFIG_ADC2_DISABLE_DAC CONFIG_ADC_DISABLE_DAC

define CONFIG_BROWNOUT_DET CONFIG_ESP32_BROWNOUT_DET

define CONFIG_BROWNOUT_DET_LVL_SEL_0 CONFIG_ESP32_BROWNOUT_DET_LVL_SEL_0

define CONFIG_COMPILER_OPTIMIZATION_LEVEL_DEBUG CONFIG_COMPILER_OPTIMIZATION_DEFAULT

define CONFIG_CONSOLE_UART_BAUDRATE CONFIG_ESP_CONSOLE_UART_BAUDRATE

define CONFIG_CONSOLE_UART_DEFAULT CONFIG_ESP_CONSOLE_UART_DEFAULT

define CONFIG_CONSOLE_UART_RX_GPIO CONFIG_ESP_CONSOLE_UART_RX_GPIO

define CONFIG_CONSOLE_UART_TX_GPIO CONFIG_ESP_CONSOLE_UART_TX_GPIO

define CONFIG_ESP32S2_PANIC_PRINT_REBOOT CONFIG_ESP_SYSTEM_PANIC_PRINT_REBOOT

define CONFIG_ESP32_APPTRACE_DEST_NONE CONFIG_APPTRACE_DEST_NONE

define CONFIG_ESP32_DEFAULT_PTHREAD_CORE_NO_AFFINITY CONFIG_PTHREAD_DEFAULT_CORE_NO_AFFINITY

define CONFIG_ESP32_PANIC_PRINT_REBOOT CONFIG_ESP_SYSTEM_PANIC_PRINT_REBOOT

define CONFIG_ESP32_PTHREAD_STACK_MIN CONFIG_PTHREAD_STACK_MIN

define CONFIG_ESP32_PTHREAD_TASK_NAME_DEFAULT CONFIG_PTHREAD_TASK_NAME_DEFAULT

define CONFIG_ESP32_PTHREAD_TASK_PRIO_DEFAULT CONFIG_PTHREAD_TASK_PRIO_DEFAULT

define CONFIG_ESP32_PTHREAD_TASK_STACK_SIZE_DEFAULT CONFIG_PTHREAD_TASK_STACK_SIZE_DEFAULT

define CONFIG_ESP32_RTC_CLOCK_SOURCE_INTERNAL_RC CONFIG_ESP32_RTC_CLK_SRC_INT_RC

define CONFIG_ESP_GRATUITOUS_ARP CONFIG_LWIP_ESP_GRATUITOUS_ARP

define CONFIG_FLASHMODE_DIO CONFIG_ESPTOOLPY_FLASHMODE_DIO

define CONFIG_FOUR_UNIVERSAL_MAC_ADDRESS CONFIG_ESP32_UNIVERSAL_MAC_ADDRESSES_FOUR

define CONFIG_GARP_TMR_INTERVAL CONFIG_LWIP_GARP_TMR_INTERVAL

define CONFIG_INT_WDT CONFIG_ESP_INT_WDT

define CONFIG_INT_WDT_CHECK_CPU1 CONFIG_ESP_INT_WDT_CHECK_CPU1

define CONFIG_INT_WDT_TIMEOUT_MS CONFIG_ESP_INT_WDT_TIMEOUT_MS

define CONFIG_IPC_TASK_STACK_SIZE CONFIG_ESP_IPC_TASK_STACK_SIZE

define CONFIG_LOG_BOOTLOADER_LEVEL_INFO CONFIG_BOOTLOADER_LOG_LEVEL_INFO

define CONFIG_MAIN_TASK_STACK_SIZE CONFIG_ESP_MAIN_TASK_STACK_SIZE

define CONFIG_MB_CONTROLLER_NOTIFY_QUEUE_SIZE CONFIG_FMB_CONTROLLER_NOTIFY_QUEUE_SIZE

define CONFIG_MB_CONTROLLER_NOTIFY_TIMEOUT CONFIG_FMB_CONTROLLER_NOTIFY_TIMEOUT

define CONFIG_MB_CONTROLLER_STACK_SIZE CONFIG_FMB_CONTROLLER_STACK_SIZE

define CONFIG_MB_EVENT_QUEUE_TIMEOUT CONFIG_FMB_EVENT_QUEUE_TIMEOUT

define CONFIG_MB_MASTER_DELAY_MS_CONVERT CONFIG_FMB_MASTER_DELAY_MS_CONVERT

define CONFIG_MB_MASTER_TIMEOUT_MS_RESPOND CONFIG_FMB_MASTER_TIMEOUT_MS_RESPOND

define CONFIG_MB_QUEUE_LENGTH CONFIG_FMB_QUEUE_LENGTH

define CONFIG_MB_SERIAL_BUF_SIZE CONFIG_FMB_SERIAL_BUF_SIZE

define CONFIG_MB_SERIAL_TASK_PRIO CONFIG_FMB_SERIAL_TASK_PRIO

define CONFIG_MB_SERIAL_TASK_STACK_SIZE CONFIG_FMB_SERIAL_TASK_STACK_SIZE

define CONFIG_MB_TIMER_GROUP CONFIG_FMB_TIMER_GROUP

define CONFIG_MB_TIMER_INDEX CONFIG_FMB_TIMER_INDEX

define CONFIG_MB_TIMER_PORT_ENABLED CONFIG_FMB_TIMER_PORT_ENABLED

define CONFIG_MONITOR_BAUD_115200B CONFIG_ESPTOOLPY_MONITOR_BAUD_115200B

define CONFIG_OPTIMIZATION_ASSERTIONS_ENABLED CONFIG_COMPILER_OPTIMIZATION_ASSERTIONS_ENABLE

define CONFIG_OPTIMIZATION_LEVEL_DEBUG CONFIG_COMPILER_OPTIMIZATION_DEFAULT

define CONFIG_POST_EVENTS_FROM_IRAM_ISR CONFIG_ESP_EVENT_POST_FROM_IRAM_ISR

define CONFIG_POST_EVENTS_FROM_ISR CONFIG_ESP_EVENT_POST_FROM_ISR

define CONFIG_REDUCE_PHY_TX_POWER CONFIG_ESP32_REDUCE_PHY_TX_POWER

define CONFIG_SEMIHOSTFS_HOST_PATH_MAX_LEN CONFIG_VFS_SEMIHOSTFS_HOST_PATH_MAX_LEN

define CONFIG_SEMIHOSTFS_MAX_MOUNT_POINTS CONFIG_VFS_SEMIHOSTFS_MAX_MOUNT_POINTS

define CONFIG_SPI_FLASH_WRITING_DANGEROUS_REGIONS_ABORTS CONFIG_SPI_FLASH_DANGEROUS_WRITE_ABORTS

define CONFIG_STACK_CHECK_NONE CONFIG_COMPILER_STACK_CHECK_MODE_NONE

define CONFIG_SUPPORT_TERMIOS CONFIG_VFS_SUPPORT_TERMIOS

define CONFIG_SUPPRESS_SELECT_DEBUG_OUTPUT CONFIG_VFS_SUPPRESS_SELECT_DEBUG_OUTPUT

define CONFIG_SYSTEM_EVENT_QUEUE_SIZE CONFIG_ESP_SYSTEM_EVENT_QUEUE_SIZE

define CONFIG_SYSTEM_EVENT_TASK_STACK_SIZE CONFIG_ESP_SYSTEM_EVENT_TASK_STACK_SIZE

define CONFIG_TASK_WDT CONFIG_ESP_TASK_WDT

define CONFIG_TASK_WDT_CHECK_IDLE_TASK_CPU0 CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU0

define CONFIG_TASK_WDT_CHECK_IDLE_TASK_CPU1 CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU1

define CONFIG_TASK_WDT_TIMEOUT_S CONFIG_ESP_TASK_WDT_TIMEOUT_S

define CONFIG_TCPIP_RECVMBOX_SIZE CONFIG_LWIP_TCPIP_RECVMBOX_SIZE

define CONFIG_TCPIP_TASK_AFFINITY_NO_AFFINITY CONFIG_LWIP_TCPIP_TASK_AFFINITY_NO_AFFINITY

define CONFIG_TCPIP_TASK_STACK_SIZE CONFIG_LWIP_TCPIP_TASK_STACK_SIZE

define CONFIG_TCP_MAXRTX CONFIG_LWIP_TCP_MAXRTX

define CONFIG_TCP_MSL CONFIG_LWIP_TCP_MSL

define CONFIG_TCP_MSS CONFIG_LWIP_TCP_MSS

define CONFIG_TCP_OVERSIZE_MSS CONFIG_LWIP_TCP_OVERSIZE_MSS

define CONFIG_TCP_QUEUE_OOSEQ CONFIG_LWIP_TCP_QUEUE_OOSEQ

define CONFIG_TCP_RECVMBOX_SIZE CONFIG_LWIP_TCP_RECVMBOX_SIZE

define CONFIG_TCP_SND_BUF_DEFAULT CONFIG_LWIP_TCP_SND_BUF_DEFAULT

define CONFIG_TCP_SYNMAXRTX CONFIG_LWIP_TCP_SYNMAXRTX

define CONFIG_TCP_WND_DEFAULT CONFIG_LWIP_TCP_WND_DEFAULT

define CONFIG_TIMER_QUEUE_LENGTH CONFIG_FREERTOS_TIMER_QUEUE_LENGTH

define CONFIG_TIMER_TASK_PRIORITY CONFIG_FREERTOS_TIMER_TASK_PRIORITY

define CONFIG_TIMER_TASK_STACK_DEPTH CONFIG_FREERTOS_TIMER_TASK_STACK_DEPTH

define CONFIG_TIMER_TASK_STACK_SIZE CONFIG_ESP_TIMER_TASK_STACK_SIZE

define CONFIG_TOOLPREFIX CONFIG_SDK_TOOLPREFIX

define CONFIG_UDP_RECVMBOX_SIZE CONFIG_LWIP_UDP_RECVMBOX_SIZE

igrr commented 3 years ago

@norventa This looks like expected behavior, as blocking operations (such as logging) are not allowed in critical sections. The abort which happens is a few lines below, next to the comment:

/* Tried to block on mutex from ISR, couldn't... rewrite your program to avoid libc interactions in ISRs! */

The comments in the code related to ISRs are incorrect. In this code, xPortCanYield checks whether task switching is allowed, i.e. that a blocking operation can be attempted. ISR context is one of the cases when blocking operations are not allowed, and a critical section (with interrupts disabled) is the other one. We need to fix the comments to mention the case of critical sections as well.

More generally, even if logging without any blocking operations was possible, it wouldn't be recommended. Since logging is slow, interrupts would get delayed for an amount of time up to a few milliseconds, and this can lead to misbehavior of some of the drivers and Wi-Fi/BT stacks. I'd recommend restructuring your code to avoid logging from critical sections.

norventa commented 3 years ago

Thank you for clarifying that.