cpu/esp32: startup info if module esp_log_startup is used

[gschorcht]

Contribution description

This PR introduces the pseudomodule esp_log_startup to control the additional information that are printed at startup for ESP32 boards. Additional startup information, including board configuration, are only printed when the esp_log_startup module is used. This reduces the amount of information that is printed by default to the console during the startup. The user can enable module esp_log_startup explicitly to get the additional startup information.

Testing procedure

Use any application to test the module with as following:

1. No additional information should be shown with the exception of the ROOM bootloader message.

   make BOARD=esp32-wroom-32 -C tests/thread_basic flash test
   

2. Additional information should be shown including the board configuration.

   USEMODULE=esp_log_startup make BOARD=esp32-wroom-32 -C tests/thread_basic/ test
   

Issues/PRs references

[gschorcht]

@benpicco What about this approach to reduce the startup information?

[gschorcht]

@benpicco @MrKevinWeiss @aabadie You all have tested ESP32 boards a lot. You all have seen the information printed by these boards during the boot process, including the board configuration. Some of these information come from the bootloader, others from RIOT's platform-specific startup procedure.

@benpicco asked for less information. I personally like these startup information. Therefore, I would like to ask what you think about the approach in this PR to print these startup information only when using the esp_log_startup module.

I tried to use DEVELHELP for it what seems to be more appropriate. However, some test applications use DEVELHELP by default because they can only be compiled when DEVELHELP is set.

[aabadie]

Wouldn't it make more sense to reuse LOG_DEBUG for all board configurations ? The default logging level is INFO so all these messages won't be printed by default. Using LOG_LEVEL=4 make, you'll get the info.

[gschorcht]

First, I would like to find an agreement on whether all these startup information (bootloader outputs including SPI flash info, used clocks, heap information, system time and board configuration) are annoying or useful and whether they should be disabled or enabled by default?

@yegorich You also used the ESP32 quite often, what do you think?

[gschorcht]

Wouldn't it make more sense to reuse LOG_DEBUG for all board configurations ? The default logging level is INFO so all these messages won't be printed by default. Using LOG_LEVEL=4 make, you'll get the info.

Since LOG_DEBUG can't be defined as make variable and has to be defined as CFLAGS option

CFLAGS='-DLOG_LEVEL=4' make BOARD=esp32-wroom-32 -C ...

it can't be used to control which bootloader is used, the one with startup information or the one without startup information.

[aabadie]

Since LOG_DEBUG can't be defined as make variable and has to be defined as CFLAGS option

This was changed some time ago (#11592)

RIOT/Makefile.include

Lines 179 to 185 in 574c7d5

	# Override LOG_LEVEL if variable is set and if CFLAGS doesn't already contain
	# a LOG_LEVEL config
	ifdef LOG_LEVEL
	ifneq (,$(filter -DLOG_LEVEL=%,$(CFLAGS)))
	CFLAGS += -DLOG_LEVEL=$(LOG_LEVEL)
	endif
	endif

[gschorcht]

This was changed some time ago (#11592)

Hm, I tried it with

LOG_LEVEL=4 make BOARD=esp32-wroom-32 -C tests/thread_basic/ flash

but it didn't work 😟 The application makefile doesn't override it.

[gschorcht]

RIOT/Makefile.include

Line 182 in 574c7d5

ifneq (,$(filter -DLOG_LEVEL=%,$(CFLAGS)))

Shouldn't it be

  ifeq (,$(filter -DLOG_LEVEL=%,$(CFLAGS)))

here?

[aabadie]

Shouldn't it be

Indeed that would be more inline with the comment

[MrKevinWeiss]

I like the info actually, have a switch to turn it on and off is a good idea. My question would be, should it be on by default?

I think so as people who are not familiar with RIOT are likely the ones to use it. Like so many make commands it can get lost in the noise. For those like @benpicco who are familiar with it and don't need the boot information it would be a lot easier disable it. Also you can add a message in the boot information to tell how to disable it...
To hide the boot information and pinouts use the HIDE_MY_STUFF=1 flag in your make call

[gschorcht]

I like the info actually, have a switch to turn it on and off is a good idea. My question would be, should it be on by default?

I think so as people who are not familiar with RIOT are likely the ones to use it. Like so many make commands it can get lost in the noise. For those like @benpicco who are familiar with it and don't need the boot information it would be a lot easier disable it. Also you can add a message in the boot information to tell how to disable it...
To hide the boot information and pinouts use the HIDE_MY_STUFF=1 flag in your make call

This would also be easy to realize with the pseudo-module esp_log_startup. If the module would be enabled by default, it would be enough to use:

DISABLE_MODULE=esp_log_startup make BOARD=esp32-wroom-32 -C ...

[benpicco]

This would also be easy to realize with the pseudo-module esp_log_startup.

A goal of RIOT is consistent behavior across different architectures. So having an arch-specific verbosity-level module is odd.

What's wrong with using the common LOG_LEVEL?

[gschorcht]

Yeah, logging for ESP32 boards is a bit special and tricky 🕶️ The ESP32 port implements its own log module

1. to produce log outputs that are as consistent as possible with the log outputs produced by SDK binary blobs we can't control and
2. to provide the log API that is required for the SDK source code parts according to their API definition.

This is realized by a bunch of macros that can be controlled by the pseudo-modules esp_log_colored and esp_log_tagged. The log module also overrides log_write which in turn uses the same macros as the SDK for consistency.

Of course, I can change it so that RIOT code uses RIOT's log_module and the ESP SDK code uses the SDK API compliant log macros. In fact, I have already a local branch here doing exactly that. This will lead to a mixture of different log output formats on ESP32 boars. The question is what more important is, the consistency of the outputs on one platform or the consistency of a part of the outputs with other platforms. I'm not sure.

What about a compromise? We let the log module as is so that the user can decide how the log output should look like. We control the startup information with the module esp_log_startup as provided by this PR and enable this module if the LOG_LEVEL is at least 4, so that user can use

LOG_LEVEL=4 make ...

The log output from RIOT part is compatible with other platforms by default.

[gschorcht]

@benpicco

What about a compromise? We let the log module as is so that the user can decide how the log output should look like. We control the startup information with the module esp_log_startup as provided by this PR and enable this module if the LOG_LEVEL is at least 4, so that user can use

LOG_LEVEL=4 make ...

The log output from RIOT part is compatible with other platforms by default.

[benpicco]

Thank you for the ping, sorry forgot about this one.

How much log output is the SDK producing anyway?
IMHO using an esp shouldn't feel 'different' than using any other architecture RIOT supports.

If the esp logging provided added value over what RIOT logging currently does, maybe we should think of adding those features to RIOT logging then.

Of how much of a different log output are we talking here anyway?

[gschorcht]

IMHO using an esp shouldn't feel 'different' than using any other architecture RIOT supports.

Agreed.

If the esp logging provided added value over what RIOT logging currently does, maybe we should think of adding those features to RIOT logging then.

The log output of ESP SDK is tagged as follows with a type, the system time in ms and a module name:

I (48346) [module] This is a message

Even though the type and the system time in ms might not be useful, tagging log outputs with the module name in a consistent format, seems to be an advantage over RIOT's log output. In RIOT each module uses its own format for tagging. I have seen

module: A message
(module) A message
[module] A message
INFO [MODULE] A message
A message

It would be great to have a consistent format over all modules in RIOT too. That's why I already opened issue #10651.

[aabadie]

Looks good in general and I like that the verbose config information is not printed by default, this is more consistent with other platforms.

I tested this PR on esp23-wroom-32 and it works as expected.

[aabadie]

All green on Murdock and tested locally with success.

ACK and go!

[gschorcht]

@aabadie Thanks for reviewing, testing and merging 😄