Where to set the logging level at compile-time?

[victorbnl]

Where is the best place to set the logging level at compile time with this project template? Running RUST_LOG="debug" cargo run does not print debug logs, I’m guessing because the variable is not passed to the ESP’s runtime environment.

The best solution would appear to be setting the log crate’s feature flag as follows, however I’d like to set a different logging level for each profile, and per-profile rustflags are currently unstable.

[profile.release]
rustflags = ["-C", "release_max_level_info"]

[profile.debug]
rustflags = ["-c", "release_max_level_debug"]

[Vollbrecht]

First you need to answer the following question: Log level of "what", as there are exist a bunch of different loglevel's for different parts. For example 2nd stage bootloader and your application code in general having different knob's.

For most of the IDF logging you can set different sdkconfig levels depending on the level. Have a look at this options. For example to set the default log level to error only you can add CONFIG_LOG_DEFAULT_LEVEL_ERROR=y to your sdkconfig.

You can have different sdkconfig files for different esp variants and profiles. For info look at our build option chapter in esp-idf-sys and check the official docu on that topic.

If you want to reduce what is actually binary size you can also use the CONFIG_LOG_MAXIMUM_LEVEL sdkconfig option.

For other runtime logging log level changes you might want to you can simply initialize the EspLogger and set its target with something like this

    esp_idf_svc::log::EspLogger::initialize_default();
    let logger = esp_idf_svc::log::EspLogger;
    logger.set_target_level("*", LevelFilter::Trace).unwrap();

[victorbnl]

I meant the logging level of the logs I print with the log crate, sorry for the lack of precision. The issue with your solution is the log level is hard-coded. Is there a place in configuration files I can put the desired logging level? Or should I use conditional compilation and do something like

#[cfg_attr(log_level = "debug")]
logger.set_target_level("*", LevelFilter::Debug)?;
#[cfg_attr(log_level = "info")]
logger.set_target_level("*", LevelFilter::Info)?;
#[cfg_attr(log_level = "warning")]
logger.set_target_level("*", LevelFilter::Warning)?;
...

Also your solution does not seem to effectively set the target level. The following code does not print anything.

esp_idf_svc::log::EspLogger::initialize_default();
let logger = esp_idf_svc::log::EspLogger;
logger.set_target_level("*", LevelFilter::Trace).unwrap();
log::debug!("Test")

[ivmarkov]

I meant the logging level of the logs I print with the log crate, sorry for the lack of precision. The issue with your solution is the log level is hard-coded. Is there a place in configuration files I can put the desired logging level? Or should I use conditional compilation and do something like

Note that "configuration files" on embedded is always compile-time as well. Just mentioning. But indeed, kind of "less" hard-coded. :)

Also your solution does not seem to effectively set the target level. The following code does not print anything.

I've tried to explain why below...

@victorbnl @Vollbrecht Let me try to summarize the status quo - as much as I understand it myself, as I feel
(a) it is not documented - completely - anywhere
(b) it is a bit involved
(c) we might have an opportunity to simplify.

@Vollbrecht - feel free to correct if you spot any inconsistencies

It is easiest to split the notion of logging into two aspects:

• Logging from Rust (with the log crate, as in warn!, info! and so on)
• Logging from ESP IDF itself (C code). Here it is crucial to understand, that logging from Rust delegates to the ESP IDF logger, so everything valid for ESP IDF applies to logging from Rust as well, but logging from Rust has a few "extra knobs", so to say. But still and in general "more verbose" logging specified on the Rust level cannot work, unless same or higher verbosity is configured on the ESP IDF level, because - and as explained below - Rust logging is currently routed via the ESP IDF logging.

(Rust code only) Logging from Rust (with the log crate) - the "extra knobs"

(Rust code only) Static (compile-time) restriction of log level

The only way to save Rust code space is - when expressing the dependency to the log crate in Cargo.toml - to use one of the following features:

• max_level_off
• max_level_error
• ...
• release_max_level_off
• release_max_level_error
• ...

(taken from here)

Setting - e.g. - log = { version = "0.4", features = ["max_level_warn"] } will ensure, that all trace!, debug! and info! macro invocations would be compiled out and thus you'll safe a very tiny bit w.r.t. performance but more importantly - you'll save in terms of code size as all the strings and formatters you type in your trace!, debug! etc. macros would be compiled out

Note that the log crate maintainers do not advise setting these features, as they have a global impact - i.e. you can only set these ONCE in your cargo dependencies' tree. If you try to set these twice - to different values - you'll get a build-time error. However, this is Embedded, so if we want to save space we should probably use these features.

Note also that the default Rust log level is max_level_trace i.e. nothing is compiled out, everything w.r.t. strings and formatters is in there, including trace!.

(Rust code only) Run-time restriction of log level

This is done with log::set_max_level. By default, once you call EspLogger::initialize_default(), it calls log::set_max_level with the DEFAULT ESP IDF logging level (see the ESP IDF section below as to what this means).

Note also that if you call at runtime log::set_max_level with a logging level higher than what you've specified with a (release_)max_level_* feature you'll achieve nothing, as the relevant macros would be compiled out anyway.

Pitfall 1: Note also that you can always call log::set_max_level with a custom level, but you'll only achieve higher logging verbosity only if the corresponding runtime logging level on the ESP IDF side is higher than or equal to what you set with log::set_max_level

ESP IDF logging (applies to Rust code too, because EspLogger calls the ESP IDF logging system)

Static (compile-time) restriction of log level

CONFIG_LOG_MAXIMUM_LEVEL in sdkconfig.defaults

• This is a compile time ALL-maximum level for all logs routed via the ESP IDF logging system
• So this is also valid for Rust logs (i.e. you might have Rust log crate set to log everything, but if you've set CONFIG_LOG_MAXIMUM_LEVEL to - say - 3 (which is the default) - then only info! and above would be logged, no matter what you do in Rust
• CONFIG_LOG_MAXIMUM_LEVEL has the same effect on ESP IDF C code as the (release_)max_level_* features have on Rust code - it causes all ESP_LOG macros in C code which are for more verbose logging than to what you set the CONFIG_LOG_MAXIMUM_LEVEL to be compiled out
• Pitfall 2: Unfortunately, CONFIG_LOG_MAXIMUM_LEVEL does not affect Rust code, so if you want to save code size in both Rust and ESP IDF C code, you need to set both the Rust (release_)max_level_* features as well as CONFIG_LOG_MAXIMUM_LEVEL

Run-time restriction of log level

This is done with the CONFIG_LOG_DEFAULT_LEVEL option in asdkconfig.defaults @Vollbrecht mentioned.
Why am I calling this "run time" when it is in fact a compile-time option?

• Because at runtime, you can override whatever you set via CONFIG_LOG_DEFAULT_LEVEL (hence the "default" word in it) with a call to esp_log_level_set() as long as... you also enable LOG_DYNAMIC_LEVEL_CONTROL in sdkconfig.defaults. Yes, ESP IDF seems over-complicated a bit here...
• Just like with CONFIG_LOG_MAXIMUM_LEVEL, CONFIG_LOG_DEFAULT_LEVEL affects also Rust logs, as these are routed via the ESP IDF console logger.

Setting custom log level on individual Rust modules and ESP-IDF components

TBD. Let's first get the global logging setup straight, and then we get here, as I might have gaps in my global level logging understanding too.

[victorbnl]

Thank you very much, very interesting explanation! So as per your instructions I tried the following steps

• Set CONFIG_LOG_MAXIMUM_LEVEL=5 in sdkconfig.defaults
• Set CONFIG_LOG_DEFAULT_LEVEL=5 in sdkconfig.defaults
• Enable the features log = { version = "0.4", features = ["max_level_trace", "release_max_level_trace"] } in Cargo.toml
• Set the max level at runtime on the log module log::set_max_level(log::LevelFilter::Trace);

And when I say the following steps I mean I did them all then ran the projects, with all the changes done. And after that, my debug messages still don’t get logged.

[ivmarkov]

There was some weird cludge w.r.t. how CONFIG_LOG_MAXIMUM_LEVEL is actually set. Try
CONFIG_LOG_MAXIMUM_LEVEL_VERBOSE=y

[ivmarkov]

And also CONFIG_LOG_DEFAULT_LEVEL_VERBOSE=y.

Once these trigger, you can reduce from there.

[Vollbrecht]

Overall your summary is correct, though the initial question was how to set it for different profiles. E.g set a different level for a release build compared to a debug build, or set a different level for lets say building against esp32c3 compared to building against a esp32 all at compile time.

I linked it in my initial answer but just to make it super clear by explicitly stating how one can do that:

• For a release and debug profile you just crate 2 sdkconfig files named sdkconfig.defaults.debug and sdkconfig.defaults.release
• Then you put in your release sdkconfig file, the following as an example CONFIG_LOG_DEFAULT_LEVEL_ERROR=y to only log errors and in your debug build CONFIG_LOG_DEFAULT_LEVEL_VERBOSE=y to log everything.

Nothing more is needed in this case, from a "global" app logging perspective. Also no other additions are needed inside your rust code. We automatically detect different sdkconfigs and apply them accordingly.

So you now can run cargo build and cargo build --release and it just works..

[victorbnl]

So now I have the following:

• features = ["max_level_trace", "release_max_level_trace"] in Cargo.toml
• log::set_max_level(log::LevelFilter::Trace); in code
• and my sdkconfig.defaults:

  CONFIG_LOG_DEFAULT_LEVEL_VERBOSE=y
  CONFIG_LOG_MAX_LEVEL_VERBOSE=y
  

• finally I did a cargo clean

Still no debug logs printed.

[ivmarkov]

Overall your summary is correct, though the initial question was how to set it for different profiles.

I think the original question was simply how the hell to see the output of Rust debug! in a project generated by esp-idf-template.
And the reason why the poster was struggling is because he could not see the connection between CONFIG_LOG_MAXIMUM_LEVEL (i.e. the ESP IDF logging) and the Rust logging control knobs.

Hence my explanation that these things are related (i.e. you can try to log from Rust as verbose as you can, but you won't see anything, unless you also increase the logging level in ESP IDF itself).

You were also saying:
"If you want to reduce what is actually binary size you can also use the CONFIG_LOG_MAXIMUM_LEVEL sdkconfig option."

... but this will not reduce anything in the Rust code. Hence why I had to explain that reduction is Rust is only achievable by using the log crate features in Cargo.toml.

My comments are as much for the original poster as they are for you and me, so that we can get a complete picture of how logging currently works (as I sometimes feel I'm forgetting details as there are too many).

... and if we can simplify something as the configuration looks a bit complicated yet still not completely flexible.
For example, currently I'm not 100% sure how to enable verbose logging in Rust, yet NOT enable verbose logging for the ESP IDF C code.

[ivmarkov]

@victorbnl

Sorry, but I just repeated your setup, and it works for me.

Here's my sdkconfig.defaults; notice that if you go with it, you need to set CONFIG_FREERTOS_IDLE_TASK_STACKSIZE=4096 as you are putting ESP IDF itself in verbose logging mode, and apparently it needs extra stack for the idle task.

# Rust often needs a bit of an extra main task stack size compared to C (the default is 3K)
CONFIG_ESP_MAIN_TASK_STACK_SIZE=8000

CONFIG_FREERTOS_IDLE_TASK_STACKSIZE=4096

# Use this to set FreeRTOS kernel tick frequency to 1000 Hz (100 Hz by default).
# This allows to use 1 ms granuality for thread sleeps (10 ms by default).
#CONFIG_FREERTOS_HZ=1000

# Workaround for https://github.com/espressif/esp-idf/issues/7631
#CONFIG_MBEDTLS_CERTIFICATE_BUNDLE=n
#CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_FULL=n

CONFIG_LOG_DEFAULT_LEVEL_VERBOSE=y
CONFIG_LOG_MAXIMUM_LEVEL_VERBOSE=y

W.r.t. Rust, main.rs is simply:

fn main() {
    // It is necessary to call this function once. Otherwise some patches to the runtime
    // implemented by esp-idf-sys might not link properly. See https://github.com/esp-rs/esp-idf-template/issues/71
    esp_idf_svc::sys::link_patches();

    // Bind the log crate to the ESP Logging facilities
    esp_idf_svc::log::EspLogger::initialize_default();

    log::debug!("Hello, world!");
}

... and NO other changes.

• features = ["max_level_trace", "release_max_level_trace"] in Cargo.toml

Not necessary. This is the default anyway

• log::set_max_level(log::LevelFilter::Trace); in code

Not necessary.

• and my sdkconfig.defaults:

  CONFIG_LOG_DEFAULT_LEVEL_VERBOSE=y
  CONFIG_LOG_MAX_LEVEL_VERBOSE=y
  

This is the only necessary thing. UPDATE: But the correct name is CONFIG_LOG_MAXIMUM_LEVEL_VERBOSE! Not that it matters, because if you don't specify CONFIG_LOG_MAXIMUM_LEVEL_* (and you don't!), then it is equal to whatever you specify CONFIG_LOG_DEFAULT_LEVEL_* to be.

• finally I did a cargo clean

Still no debug logs printed.

Are you building in release or debug? Though it should not matter...

[ivmarkov]

Related: esp-rs/esp-idf-svc#458