espressif / esp-idf

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

LOG_LOCAL_LEVEL has not functioning like in v4.3.2 on v4.4 (IDFGH-6950) #8570

Open ankit-thealchemist opened 2 years ago

ankit-thealchemist commented 2 years ago

Environment

In the idf version v4.3.2 we can increase the log level in the file by applying the #define LOG_LOCAL_LEVEL. This is the super helpful in developing the code, we can set the local level to be higher than what we defined in the menuconfig.In this way we can debug only that file without bloating the console. but in v4.4(tag) this functionally has not been provided. To debug a particular file we need to compile the whole app by increasing the log level, and apply the #define LOG_LOCAL_LEVEL in each and every file to downgrade the log verbosity, still the console has been bloated any way. is there is any work around to get the previous facility?

igrr commented 2 years ago

Thanks for reporting this issue @ankit-thealchemist.

I think you can achieve this selective log level increase by setting CONFIG_LOG_MAXIMUM_LEVEL to the desired maximum log level (e.g. DEBUG or VERBOSE). At the same time CONFIG_LOG_DEFAULT_LEVEL can stay equal to INFO.

At run time, you can call esp_log_level_set("your_tag", ESP_LOG_DEBUG); to increase the debug log level for the desired module.


I think the change to the behavior of LOG_LOCAL_LEVEL was a side effect of adding this new CONFIG_LOG_MAXIMUM_LEVEL option. I'm sorry that we have missed that this use case will no longer work as it did previously. Now LOG_LOCAL_LEVEL is always equal to CONFIG_LOG_MAXIMUM_LEVEL, but the run-time setting for "default log level" is set to CONFIG_LOG_DEFAULT_LEVEL. Therefore all the logs at levels between CONFIG_LOG_DEFAULT_LEVEL and CONFIG_LOG_MAXIMUM_LEVEL are built into the application, but are skipped at runtime unless esp_log_level_set is called to override that.

I think we can restore the previous behavior if we handle the following case:

It looks a bit weird but it seems like this will restore the functionality of LOG_LOCAL_LEVEL in IDF v4.3 and older. That is, unless the user changes the new CONFIG_LOG_MAXIMUM_LEVEL option.

suda-morris commented 2 years ago

Selective log level example: https://github.com/espressif/esp-idf/blob/master/components/driver/gptimer.c#L13 and https://github.com/espressif/esp-idf/blob/master/components/driver/gptimer.c#L345

ankit-thealchemist commented 2 years ago

Selective log level example: https://github.com/espressif/esp-idf/blob/master/components/driver/gptimer.c#L13 and https://github.com/espressif/esp-idf/blob/master/components/driver/gptimer.c#L345

I appreciate your intention for helping others. Sadly this example will not work if we select esp-idf v4.4 and default log level to info.

ankit-thealchemist commented 2 years ago

thanks @igrr for replying!

The whole problem is I use the filename and line number as tags while developing the application. I pretty useful in quickly jump to the line in the editor. Just use ctrl + click, and you quickly jump to that particular file and line number. This cannot be achieved using esp_log_write function!!

igrr commented 2 years ago

This cannot be achieved using esp_log_write function

Did you mean to say that this can't be achieved using esp_log_level_set function (because for every log line the tag is different)?

As far as I can tell, for "normal" tags which are the same for the whole file the suggestion from @suda-morris works okay.

ankit-thealchemist commented 2 years ago

@igrr yes.. exactly, different tags...

pickaxprograms commented 2 years ago

@ankit-thealchemist if you want filename/line num tags, just create wrappers that look something like this for the different levels: #define ESP_LOGEF(x, fmt, ...) ESP_LOGE(x, "%s[%d]:" fmt, __FILE__, __LINE__, ##__VA_ARGS__)

emmpe commented 2 years ago

I also experienced problems in v.4.4.1 regarding changing the logging level on component scope described in https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/system/log.html: _target_compile_definitions(${COMPONENT_LIB} PUBLIC "-DLOG_LOCAL_LEVEL=ESP_LOGVERBOSE").

I did update the CONFIG_LOG_MAXIMUM_LEVEL.

To make it work as described in documentation I had to do the following changes in the log-component:

components/log/include/esp_log.h:

ifndef LOG_LOCAL_LEVEL

ifndef BOOTLOADER_BUILD

-#define LOG_LOCAL_LEVEL CONFIG_LOG_MAXIMUM_LEVEL +#define LOG_LOCAL_LEVEL CONFIG_LOG_DEFAULT_LEVEL

else

define LOG_LOCAL_LEVEL CONFIG_BOOTLOADER_LOG_LEVEL

endif

and in components/log/log.c: -esp_log_level_t esp_log_default_level = CONFIG_LOG_DEFAULT_LEVEL; +esp_log_level_t esp_log_default_level = CONFIG_LOG_MAXIMUM_LEVEL;

Is this correct or did I misunderstand the documentation?

rodmaz commented 2 years ago

I can confirm this problem also occurs in v5.0.0-dev. Could not find a way to increase logging level of a single component. The define LOG_LOCAL_LEVEL is set to 5 (verbose) in my component but no ESP_LOGV is shown.

Logiase commented 2 years ago

v4.4.2 still not working as the documents says.

matiasstack commented 1 year ago

I can also confirm this is still an issue with 4.4.2. The documentation still says that the macro should work (#define LOG_LOCAL_LEVEL ESP_LOG_VERBOSE), but it doesn't. Increasing CONFIG_LOG_MAXIMUM_LEVEL and using esp_log_level_set at runtime works, but it isn't as convenient as just overriding it in each file.

gonzzor commented 1 year ago

Same issue with v5.0-rc1. It doesn't work as described in the documentation, with regards to #define LOG_LOCAL_LEVEL before including esp_log.h.

Elijahg commented 1 year ago

I am also seeing this still with 5.0. LOG_LEVEL_LOCAL appears to be completely ignored. Setting the following to raise the logging level for a specific file: CONFIG_LOG_MAXIMUM_LEVEL to DEBUG CONFIG_LOG_DEFAULT_LEVEL to WARN

define LOG_LOCAL_LEVEL ESP_LOG_INFO (before including esp_log.h)

Results in only warnings output, including the file where LOG_LOCAL_LEVEL ESP_LOG_INFO is set.

Doing the opposite and setting CONFIG_LOG_DEFAULT_LEVEL to INFO and lowering the log level in a specific file doesn't work either.

As well as this the documentation needs to make it clearer what "above" really means.

@igrr Is there any update on this? It's been an issue for a almost a year now and is quite an important feature.

AshUK commented 1 year ago

It's worth emphasising the importance of this. Most developers will be using debugging logs to develop and iterate on their fw applications. JTAG currently uses too many pins as viable substitute and there is no other two wire debug interface. Being able to quickly toggle a define at the top of the file is very useful and offers a quicker and pleasant experience than having to declare a bunch of esp_log_level_set()'s.

igrr commented 1 year ago

@AshUK Correct me if I'm wrong, but it is not necessary to do a bunch of esp_log_level_set()'s to show the logs compiled at custom LOG_LOCAL_LEVEL. Only one call should be sufficient:

#define LOG_LOCAL_LEVEL ESP_LOG_DEBUG
#include "esp_log.h"
static const char* TAG = "example";
void app_main(void)
{
    esp_log_level_set("*", ESP_LOG_DEBUG);
    ESP_LOGD(TAG, "hello world");
}

The example above, with CONFIG_LOG_DEFAULT_LEVEL_INFO=y and CONFIG_LOG_MAXIMUM_EQUALS_DEFAULT=y produces

...
W (300) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (314) app_start: Starting scheduler on CPU0
I (319) app_start: Starting scheduler on CPU1
I (319) main_task: Started on CPU0
I (329) main_task: Calling app_main()
D (329) example: hello world
I (329) main_task: Returned from app_main()

I do acknowledge this is a breaking change from v4.3, and we didn't update the documentation to explain it!


For the sake of others who might be reading this thread later, I also want to comment on

Most developers will be using debugging logs to develop and iterate on their fw applications. JTAG currently uses too many pins as viable substitute and there is no other two wire debug interface.

Precisely for this reason, in ESP32-C3, ESP32-S3 and later chips we have added the USB_SERIAL_JTAG interface which provides a serial console and a JTAG adapter over USB, using two pins. I do understand you might be using an earlier chip, but JTAG debugging is much more accessible now than it was before. (Of course, not a reason to not fix this particular bug.)

AgainPsychoX commented 1 year ago

Another workaround: Redefine lower logging levels macros to use higher levels:

#undef ESP_LOGV
#undef ESP_LOGD
#define ESP_LOGV(...) ESP_LOGI(__VA_ARGS__)
#define ESP_LOGD(...) ESP_LOGI(__VA_ARGS__)
higaski commented 1 year ago

Any news on this issue? Is this considered a bug or an error in the documentation at the moment? The note on the log docs still says

The function esp_log_level_set() cannot set logging levels higher than specified by CONFIG_LOG_MAXIMUM_LEVEL. To increase log level for a specific file above this maximum at compile time, use the macro LOG_LOCAL_LEVEL (see the details below).

As far as I can tell the second sentence isn't true at this point. LOG_LOCAL_LEVEL can't even increase the level beyond CONFIG_LOG_DEFAULT_LEVEL.

alambin commented 1 year ago

Seems like they call it new "feature" :) There was convenient way just by 1 line to change log level wherever you want. Now you have to mess with config options, call esp_log_level_set() for every(!) used tag in your project. @igrr, please pay attention how many developers here (and many more who didn't come here) are looking for workaround just to get previous behavior. May be this new "feature" is not that good and may be ESP team can think about it and provide some way to increase log level in previous way? :)

igrr commented 1 year ago

@alambin I do agree this is a bug which should be fixed, not a feature.

In the meantime, could you please check if the suggestion about using esp_log_level_set("*", ESP_LOG_DEBUG); posted above helps? https://github.com/espressif/esp-idf/issues/8570#issuecomment-1379272812

alambin commented 1 year ago

Well, I didn't check tag "*", but I guess it will lead to log level of all components to increase. It will result in flood of logs, which I want to avoid, because I'm not interested in verbose logs from ESP system components, I need verbose level only for my project files. This is why nowI had to use esp_log_level_set() 19 times for each of my tags.

igrr commented 1 year ago

Sorry for not explaining it clearly, i meant the following steps:

Please see this comment: https://github.com/espressif/esp-idf/issues/8570#issuecomment-1379272812

alambin commented 1 year ago

@igrr, hm, you are right. It works and no flood of messages from system components of ESP, as I expected. Thank you!

newflydd commented 1 year ago

v5.01 still not working as the documents says.

I found the code at esp_log.h 319 line:

#ifdef BOOTLOADER_BUILD
#define _ESP_LOG_EARLY_ENABLED(log_level) (LOG_LOCAL_LEVEL >= (log_level))
#else
/* For early log, there is no log tag filtering. So we want to log only if both the LOG_LOCAL_LEVEL and the
   currently configured min log level are higher than the log level */
#define _ESP_LOG_EARLY_ENABLED(log_level) (LOG_LOCAL_LEVEL >= (log_level) && esp_log_default_level >= (log_level))
#endif

#define ESP_LOG_EARLY_IMPL(tag, format, log_level, log_tag_letter, ...) do {                             \
        if (_ESP_LOG_EARLY_ENABLED(log_level)) {                                                         \
            esp_rom_printf(LOG_FORMAT(log_tag_letter, format), esp_log_timestamp(), tag, ##__VA_ARGS__); \
        }} while(0)

so I add the macro like :

#define BOOTLOADER_BUILD 1
#define LOG_LOCAL_LEVEL ESP_LOG_VERBOSE
#include <esp_log.h>

so it woks!!!

but when I use the hex print out, it still won't work, how saddly I am.

ESP_LOG_BUFFER_HEX_LEVEL("lcd:tran", buffer, buf_idx, ESP_LOG_VERBOSE);

it don't work.

I like RTThread's system, it is beautiful. The ESP_LOG is very ugly.

ankit-thealchemist commented 1 year ago

Sorry for not explaining it clearly, i meant the following steps:

  • add a LOG_LOCAL_LEVEL macro to your source file, increasing the log level for the specific file
  • call esp_log_level_set("*", ...) from app_main.

Please see this comment: #8570 (comment)

Thanks @igrr Its works as expected..... It atleast solves my problem for which I created the thread..

r-downham commented 1 month ago

Any progress on this yet? - Requirement is to up the logging level for a component, but I get the dreaded "LOG_LOCAL_LEVEL" redefined warning. - Would be nice to get rid of it...

header file #pragma once #define LOG_LOCAL_LEVEL ESP_LOG_DEBUG #include "esp_log.h"

Causes warning. D:/esp32/components/ezWifiLib/include/ezWifi/ezWifi.h:10: warning: "LOG_LOCAL_LEVEL" redefined 10 #define LOG_LOCAL_LEVEL ESP_LOG_DEBUG

D:/espressif/frameworks/esp-idf-v5.2.2/components/log/include/esp_log.h:179: note: this is the location of the previous definition 179 | #define LOG_LOCAL_LEVEL CONFIG_LOG_MAXIMUM_LEVEL

KonstantinKondrashov commented 1 month ago

@r-downham! In IDF, the LOG_LOCAL_LEVEL is defined in esp_log.h file if it was not defined before. Seems in your case LOG_LOCAL_LEVEL was defined somewhere else, before.

https://github.com/espressif/esp-idf/blob/v5.2.2/components/log/include/esp_log.h#L177-L183

#ifndef LOG_LOCAL_LEVEL
#ifndef BOOTLOADER_BUILD
#define LOG_LOCAL_LEVEL  CONFIG_LOG_MAXIMUM_LEVEL
#else
#define LOG_LOCAL_LEVEL  CONFIG_BOOTLOADER_LOG_LEVEL
#endif
#endif

As a workaround you can use #undef, but better is to figure out where it was defined:

#undef LOG_LOCAL_LEVEL
r-downham commented 1 month ago

Thank you "KonstantinKondrashov" for your response, but it does not solve the issue. I need to provide a better explanation – I will attempt to keep it brief. My project consists of a number of components which are maintained outside of the main project. A number of these external components require logging facilities and therefore

#include “esp_log.h”.

in their associated header file. - it appears that this is why the warning is being generated (i.e. LOG_LOCAL_LEVEL has already been defined).

(I was of the impression that ‘project wide’ #defines needed to be included in the project CMakeLists.txt using the directive add_compile_definitions(…) eg .

add_compile_definitions(EZ_WIFI_DEBUG=1)

so I am not sure why #defines from #include “esp_log.h” files in other component header files are having this effect?).

For one component (the WiFi component) I want to enable DEBUG logging messages so following the Espressif documentation (see below) I define in its header file

#define LOG_LOCAL_LEVEL ESP_LOG_DEBUG
#include "esp_log.h"

And by calling the following in the associated cpp file I get the expected and required behaviour i.e. debug logging messages.

esp_log_level_set("ezWifi", ESP_LOG_DEBUG);

However this causes the warning: "LOG_LOCAL_LEVEL" redefined to be generated.

If I follow the 2nd 'recommendation' from the documentation i.e. "At component scope, define it in the component CMakeLists:" (see below) and add

target_compile_definitions(${COMPONENT_LIB} PUBLIC "-DLOG_LOCAL_LEVEL=ESP_LOG_VERBOSE")

to the components CMakeLists.txt file the warning goes away, but so does the expected behaviour i.e. no debug logging message are generated.

I do find the logging documentation for this requirement a bit confusing as it appears there are two 'recommendations' to achieve what I require. (perhaps I am interpreting it incorrectly?)

https://docs.espressif.com/projects/esp-idf/en/stable/esp32/api-reference/system/log.html

image

Be very grateful if you can get me back on the right track...

KonstantinKondrashov commented 1 month ago

@r-downham. Seems I understand why did not get this warning.

ezWifi.h:

define LOG_LOCAL_LEVEL ESP_LOG_DEBUG

include "esp_log.h"

main.c:

include "esp_log.h" // at this point the LOG_LOCAL_LEVEL is not defined and, LOG_LOCAL_LEVEL will be defined inside

inlude "ezWifi.h" // unconditional second times defines LOG_LOCAL_LEVEL

The LOG_LOCAL_LEVEL definition can not be used in header files, or you have to ensure the correct order of the includes. If you look at how it is used in IDF components, you notice that it is defined always in the *.c file, not in header files.

r-downham commented 1 month ago

@KonstantinKondrashov - Thank you, placing the #define LOG_LOCAL_LEVEL ESP_LOG_DEBUG into the .cpp file appears to have fixed the issue.

My header file is now starts

#pragma once
#include "esp_wifi.h"
#include "esp_event.h"
#include "esp_log.h"

And the associated c++ file is now starts

#define LOG_LOCAL_LEVEL ESP_LOG_DEBUG
#include "ezWifi/ezWifi.h"

And all is working as required.

Out of interest, can describe a context in which the option to “define in the component CMakeLists” would apply?

image https://docs.espressif.com/projects/esp-idf/en/stable/esp32/api-reference/system/log.html