Debug logging from adc_set_init_code (on main thread) causing an abort because it thinks it calls from an ISR (IDFGH-4233)

[william-ferguson-au]

Environment

• Development Kit: none
• Module or chip used: ESP32-S2
• IDF version: v4.3-dev-1197-g8bc19ba89
• Build System: idf.py
• Compiler version (run ``xtensa-esp32-elf-gcc : (crosstool-NG esp-2020r3) 8.4.0
• Operating System: Windows
• (Windows only) environment type: ESP Command Prompt
• Using an IDE?: CLion
• Power Supply: |Battery

Problem Description

When I set logging to debug and switch WiFi logging to debug, on start up (from the main thread) when my app attempts to read the battery voltage it aborts because locks.c thinks that I am logging from within an ISR.

Expected Behavior

That it would log he debug message instead of aborting.

Actual Behavior

System aborts and restarts.

Steps to reproduce

1. idf.py menuconfig
2. Component Config->WiFi->Enable WiFi debug log == true
3. Component Config->WiFi->Enable WiFi debug log -> log level == Verbose
4. Component Config->WiFi->Enable WiFi debug level -> Wifi Debug log submodule = true
5. Component Config->WiFi->Enable WiFi debug level -> Wifi Debug log submodule -> SubModule All == true
6. Component Config->Log output ->Default log verbosity == Verbose
7. Run app

Code to reproduce this issue

#include <esp_log.h>
#include <hal/rtc_hal.h>
#include <driver/adc_common.h>
#include <nvs_flash.h>
#include <freertos/FreeRTOS.h>
#include <freertos/task.h>

extern "C" {
	void app_main();
}

static const uint16_t LOOP_DELAY_MILLIS = 1000;

static const char *TAG = "my_main";

static const gpio_num_t CHG_TS_PIN             = GPIO_NUM_15;     // Control
static const gpio_num_t ADC_VBAT_PIN           = GPIO_NUM_7;       // SENSOR_VP Pin
static const adc1_channel_t ADC_VBAT_CHANNEL   = ADC1_CHANNEL_6;

/******************************************************************************
 *
 * Main
 *
 *****************************************************************************/
void app_main(void) {

    // Setup
    ESP_LOGI(TAG, "Logger initialised");

    ESP_ERROR_CHECK(nvs_flash_init());

    /* Reset GPIOs */
    ESP_ERROR_CHECK(gpio_reset_pin(ADC_VBAT_PIN));
    ESP_ERROR_CHECK(gpio_reset_pin(CHG_TS_PIN));
    ESP_ERROR_CHECK(gpio_set_direction(CHG_TS_PIN, GPIO_MODE_INPUT_OUTPUT));
    ESP_ERROR_CHECK(gpio_set_pull_mode(CHG_TS_PIN, GPIO_FLOATING));

    ESP_LOGI(TAG, "Disable Charging");
    gpio_set_level(CHG_TS_PIN, 0);

    uint32_t adc_reading = adc1_get_raw((adc1_channel_t) ADC_VBAT_CHANNEL);

    ESP_LOGI(TAG, "Finished setup adc_read=%d", adc_reading);

    while (true) {
        vTaskDelay(LOOP_DELAY_MILLIS / portTICK_PERIOD_MS);
    }
}

Debug Logs

I (820) my_main: Logger initialised
D (820) partition: Loading the partition table
I (840) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (840) gpio: GPIO[15]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (850) my_main: Disable Charging

abort() was called at PC 0x40025faa on core 0
0x40025faa: lock_acquire_generic at E:/Dev/Espressif/esp-idf/components/newlib/locks.c:142

Backtrace:0x4002952f:0x3ffc4950 0x40029d65:0x3ffc4970 0x4002e19a:0x3ffc4990 0x40025faa:0x3ffc4a00 0x400260d1:0x3ffc4a30 0x40092d8e:0x3ffc4a50 0x40095d9d:0x3ffc4d60 0x4009a121:0x3ffc4d90 0x4002e061:0x3ffc4dc0 0x4
00881c2:0x3ffc4e10 0x400858cb:0x3ffc4e50 0x40029dca:0x3ffc4e70 0x40029d6d:0x3ffc4e90
0x4002952f: panic_abort at E:/Dev/Espressif/esp-idf/components/esp_system/panic.c:349

0x40029d65: esp_system_abort at E:/Dev/Espressif/esp-idf/components/esp_system/system_api.c:104

0x4002e19a: abort at E:/Dev/Espressif/esp-idf/components/newlib/abort.c:46

0x40025faa: lock_acquire_generic at E:/Dev/Espressif/esp-idf/components/newlib/locks.c:142

0x400260d1: _lock_acquire_recursive at E:/Dev/Espressif/esp-idf/components/newlib/locks.c:170

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

0x40095d9d: vprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/newlib/newlib/libc/stdio/vprintf.c:34

0x4009a121: esp_log_writev at E:/Dev/Espressif/esp-idf/components/log/log.c:189

0x4002e061: esp_log_write at E:/Dev/Espressif/esp-idf/components/log/log.c:199

0x400881c2: adc_set_init_code at E:/Dev/Espressif/esp-idf/components/driver/adc_common.c:248
(inlined by) adc1_get_raw at E:/Dev/Espressif/esp-idf/components/driver/adc_common.c:345

0x400858cb: app_main at e:\source\wylas\beamatouch\build/../main/main.cpp:57 (discriminator 8)

0x40029dca: main_task at E:/Dev/Espressif/esp-idf/components/freertos/xtensa/port.c:535

0x40029d6d: vPortTaskWrapper at E:/Dev/Espressif/esp-idf/components/freertos/xtensa/port.c:169

[Alvin1Zhang]

Thanks for reporting.

[albertyue]

The same issue was found in idf-v4.2.1