Arduino-esp32: Honor the ESP_LOGx logging macros

[nkolban]

The desire here is to create C++ source code that will compile and run as cleanly as possible under both the Arduino environment and the ESP-IDF environment. This specific issue relates to the use of the ESP_LOGx macros.

When writing C/C++ code in ESP-IDF, we use the macros ESP_LOGx() to write diagnostics to the serial console. The ESP_LOG macros have a number of variants each at a different level of logging such as ERROR, WARNING, VERBOSE, DEBUG etc. When compiled, the code will only log messages if they are at the configured level or higher. For example, ERROR level will not log WARNING. WARNING level will not log DEBUG. DEBUG level will not log VERBOSE etc.

The default in the Arduino environment is ERROR only.

There is a compile time directive found in the Arduino IDE that allows one to set a logging level. This results in a compilation time variable called CORE_DEBUG_LEVEL being set.

However ... and here is the punch line, the CORE_DEBUG_LEVEL does not affect the ESP_LOGx functions.

This issue asks that the setting of the CORE_DEBUG_LEVEL also affect the ESP_LOGx functions.

The source change for this is relatively straight forward but before making that change and issuing a pull-request, the purpose of this issue is to seek permission to make the change and issue a pull.

The logic suggestion would change the implementation of initArduino() to set the esp_log_level_set() flag as a function of the value of CORE_DEBUG_LEVEL. This code change would maintain status quo for existing Arduino logging but would embrace and engage ESP-IDF debug logging using ESP_LOGx() as part of the story.

[me-no-dev]

Arduino has its own logging facility;)

[igrr]

Well, the question here is how to support components written for IDF within Arduino system. One could say that such components must be modified to use Arduino logging macros, but that would imply maintenance burden for those who want their components to be used both in Arduino and in IDF (i.e. they have to provide two versions with different logging calls).

Another alternative is to create some wrapper macros, e.g. KLOG_E, KLOG_D, etc, which would decay to either IDF logging macros or Arduino logging macros, depending on the build flags. That would achieve the goal of having one code working in Arduino and IDF, but would still require the maintainer (@nkolban) go through his code base replacing all the logging macros, which is probably what he wants to avoid.

[me-no-dev]

I'm not particularly fond of IDF's logging facility, because it's controlled both by compile flags and also allow some runtime changes (but not all). That in effect means that most debug statements are actually compiled, regardless if you want to see them or not and at the same time switching serials is also not possible (all debug goes to UART0 or whatever the build flag is).
In order for seamless switch to work when Arduino is included, would mean that the wrappers need to be written for every piece that wants to do it (unless it's actually added to IDF itself).

[igrr]

Okay, if i understand correctly, we need to address the following issues:

1. In IDF, logging statements are compiled in depending on CONFIG_LOG_LEVEL defined in sdkconfig. Since IDF is shipped as precompiled libraries, log level can only be set when these libraries are produced, and can not be modified when during Arduino build process.

2. In addition to the above, we have a part of IDF (WiFi stack) with is always built at INFO log level, and this can not be controlled even at IDF build time. In other words, it is possible to make WiFi stack emit less that INFO (using esp_log_level_set at runtime) but it is not possible to make it emit more (i.e. DEBUG or VERBOSE)

3. IDF prints all the log output to stdout, which, again, is set to the default UART assigned in sdkconfig. It is possible to reassign stdout to another UART using freopen, but this must be done in each task which is already created.

For the first and second issue, i'd say that CONFIG_LOG_LEVEL can be set to INFO at IDF build time. Then you can change log level at runtime between INFO, WARNING, ERROR, and NONE, depending on Arduino build flags.

The third issue is fairly easy to solve. IDF allows redirection of log output to an arbitrary vprintf-like function, which can be set using esp_log_set_vprintf. You can, for example, redirect log output to another UART, or to a socket, or to the host over JTAG connection. This can be hooked into some function on Arduino side which knows which UART to print to.

[nkolban]

Until we come up with a design decision that may or may not be reflected in the code base of the Arduino sub-project, here is a workaround that can enable ESP_LOGx log output that ... so far ... seems to work.

Recipe:

1. Edit <Arduino>/hardware/espressif/esp32/tools/sdk/include/config/sdkconfig.h
2. Find the line which reads

#define CONFIG_LOG_DEFAULT_LEVEL 1

1. Change the line to

#define CONFIG_LOG_DEFAULT_LEVEL 5

1. In your Arduino sketch, include esp_log.h
2. In your setup() function, add:

esp_log_level_set("*", ESP_LOG_VERBOSE);

Rebuild all and you should now see all levels of ESP_LOGx diagnostics in the console output.

[me-no-dev]

I'll repeat my issue again: If debug level is lowered during the IDF lib compilation, all debug code will be compiled as well. And it might look small to some, but in reality many new lines will be compiled.
I can think and integrate some sort of the workaround above, so things that are build with the sketch can use ESP_LOGx, but keep all debug code away from the rest of the core libs (ERROR should be sufficient).

[copercini]

Implemented here: https://github.com/espressif/arduino-esp32/commit/409c75da042192ba5dbeb13cbde6c41e0674ed6e

=)

[az-z]

And what is the magic combination now, @copercini ? it seems that only CORE_DEBUG_LEVEL has any effect on the logs and esp_log_level_set and TAGS are completely ignored.

#include <Arduino.h>
#include "esp32-hal-log.h"
...
static const char *TAG = "AW";


void setup() {
    delay(3000);
    Serial.begin(9600);

    esp_log_level_set("*",ESP_LOG_INFO);
        ESP_LOGE(TAG,"Attempting to connect to SSID: \n ");
        ESP_LOGW(TAG,"Attempting to connect to SSID: \n ");
        ESP_LOGI(TAG,"Attempting to connect to SSID: \n ");
        ESP_LOGD(TAG,"Attempting to connect to SSID: \n ");
        ESP_LOGV(TAG,"Attempting to connect to SSID: \n ");
}

with PIO :
build_flags = -DCORE_DEBUG_LEVEL=4
yields: