ESP_LOGx running on multiple cores cause message corruption

italocjs commented 3 months ago

Board

ESP32 WROOM 32E 16MB

Device Description

unrelated, using devkit or proprietary board has the same effect

Hardware Configuration

using serial0 to debug

Version

latest master (checkout manually)

IDE Name

Platformio + ESPIDF + Arduino as component

Operating System

Unrelated

Flash frequency

240MHZ

PSRAM enabled

yes

Upload speed

115200

Description

When ESP_LOGx is used (redirecting to arduino logging function) some messages sent by both cores get corrupted, Single core does not present any issue. This is likely a missing semaphore or mutex handling on the wrapper function, i will investigate this further and if i find a solution will add an PR.

Example of expected output:

Expected message on core0: [ 1000][I][core0test.cpp:36] update(): [ErrorManager] message01_0123456789
Expected message on core1: [ 1001][I][core1test.cpp:36] update(): [ErrorManager] message02_0123456789

Actual output:

 [ 1000][I][core0test.cpp:36] update(): [ErrorManager] messa[ 1001][I][core1test.cpp:36] update(): [ErrorManager] message02_0123456789

More details:

[    60][I][port_tools.cpp:377] print_device_information(): [port_tools] This is esp32 chip with 2 CPU core(s), WiFi/BTBLE, silicon revision v0.3
[    72][I][port_tools.cpp:386] print_device_information(): [port_tools] 16MB external flash
[    82][I][port_tools.cpp:389] print_device_information(): [port_tools] Minimum free heap size now: 178784 bytes
[    93][I][port_tools.cpp:393] print_device_information(): [port_tools] MAC Address: 00:00:00:01:84:E4
[   103][I][port_tools.cpp:396] print_device_information(): [port_tools] CHIP_ID: 99556 | CPU FREQ 240 | SDK VERSION 4.4.7 | FIRMWARE VERSION TRACK HW1.3.3 FW4.3.5
[   118][I][port_tools.cpp:400] print_device_information(): [port_tools] LAST RESET REASON: Power on
[   128][I][port_tools.cpp:401] print_device_information(): [port_tools] Author: github/italocjs from July 2023 to Jul  2 2024
[   140][I][entrypoint_esp32dev.h:28] setup_safety_watchdogs(): [entry_esp32dev] Task watchdogs enabled - 20s timeout
[   151][I][entrypoint_esp32dev.h:36] setup_safety_watchdogs(): [entry_esp32dev] RTC_WDT_STAGE0 Watchdog protection enabled - 9s timeout

Platformio.ini

;This platformio.ini file is good for usage in WSL
[env:native]
lib_ldf_mode = deep+
test_framework = googletest
test_ignore = test_esp32dev
platform = native
build_flags = -D USE_NATIVE_ENVIRONMENT

lib_deps = 
    ; not used on native env

; extra_scripts = scripts/build_doxygen.py

[env:esp32dev]
build_type = debug
test_framework = googletest
test_ignore = test_native
platform = espressif32
board = simovatrack130
framework = arduino, espidf
platform_packages =
    framework-arduinoespressif32 @ https://github.com/italocjs/arduino-esp32.git#idf-release/v4.4
    ; framework-arduinoespressif32 @ https://github.com/espressif/arduino-esp32.git#idf-release/v4.4

board_build.partitions = partitions.csv
build_flags = 
    -D USE_ESP32_ENVIRONMENT
    ; -Wall                ; Enable all warnings
    ; -Wno-error           ; Ensure warnings are not treated as errors

upload_speed = 921600
monitor_speed = 115200
; monitor_filters = esp32_exception_decoder 
monitor_filters = 
    esp32_exception_decoder
    send_on_enter

lib_deps = 
    adafruit/Adafruit Unified Sensor
    adafruit/Adafruit BusIO
    adafruit/Adafruit ADXL343
    https://github.com/italocjs/DFRobot_LIS.git
    https://github.com/italocjs/geofencing_esp32.git
    https://github.com/italocjs/NuS-NimBLE-Serial
    mprograms/QMC5883LCompass
    adafruit/RTClib
    mikalhart/TinyGPSPlus
    bblanchon/ArduinoJson

; extra_scripts = esp32_exception_decoder.py

I am also attaching the sdkconfig used.

[sdkconfig.esp32dev.txt](https://github.com/user-attachments/files/16075961/sdkconfig.esp32dev.txt)

### Sketch

```cpp
#include <Arduino.h>
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_log.h"

#define TAG "TASK_LOG"

// Task 1 function
void task1(void *pvParameters) {
    while (true) {
        ESP_LOGI(TAG, "Task 1 is running");
        vTaskDelay(1 / portTICK_PERIOD_MS); // Delay for 1 ms
    }
}

// Task 2 function
void task2(void *pvParameters) {
    while (true) {
        ESP_LOGI(TAG, "Task 2 is running");
        vTaskDelay(1 / portTICK_PERIOD_MS); // Delay for 1 ms
    }
}

void setup() {
    Serial.begin(115200);
    // Create Task 1
    xTaskCreate(task1, "Task 1", 2048, NULL, 1, NULL);
    // Create Task 2
    xTaskCreate(task2, "Task 2", 2048, NULL, 1, NULL);
}

void loop() {
    // Empty loop
}

Debug Message

added above

Other Steps to Reproduce

No response

I have checked existing issues, online documentation and the Troubleshooting Guide

[X] I confirm I have checked existing issues, online documentation and Troubleshooting guide.

me-no-dev commented 3 months ago

Semaphores to core logs is a bad idea. Point is data to go out as fast as possible and not hold any task/interrupt. Logging for us is just the same as ESP-IDF's log, we more or less call the same functions to print logs

italocjs commented 3 months ago

I see your point, there will be a lot of cases where that could indeed cause issues. I'll write an wrapper for my "less critical" logs and try to keep them from clashing with ESPLOGx.

espressif / arduino-esp32