[PATCH v2 3/4] dm: core: migrate debug() messages to use dm_warn

[Quentin Schulz]

Hi Alexander,

On 10/2/24 10:37 AM, Alexander Dahl wrote:
> Hello Quentin,
> 
> sorry for being late to the party, but I just tested v2024.10-rc6 and
> my console output looks like this now:
> 
>      ofnode_read_bool: bootph-all: true
>      ofnode_read_u32_array: ranges: ofnode_read_bool: bootph-all: false
>      ofnode_read_bool: bootph-some-ram: false
>      ofnode_read_bool: bootph-pre-ram: false
>      ofnode_read_bool: bootph-pre-sram: false
>      ofnode_read_bool: u-boot,dm-pre-reloc: false
>      ofnode_read_bool: u-boot,dm-pre-proper: false
>      ofnode_read_bool: u-boot,dm-spl: false
>      ofnode_read_bool: u-boot,dm-tpl: false
>      ofnode_read_bool: u-boot,dm-vpl: false
>      ofnode_read_bool: bootph-all: false
>      ofnode_read_bool: bootph-some-ram: false
>      ofnode_read_bool: bootph-pre-ram: false
>      ofnode_read_bool: bootph-pre-sram: false
>      ofnode_read_bool: u-boot,dm-pre-reloc: false
>      ofnode_read_bool: u-boot,dm-pre-proper: false
>      ofnode_read_bool: u-boot,dm-spl: false
>      ofnode_read_bool: u-boot,dm-tpl: false
>      ofnode_read_bool: u-boot,dm-vpl: false
>      ofnode_read_bool: bootph-all: true
>      ofnode_read_u32_array: ranges: ofnode_read_bool: bootph-all: true
>      ofnode_read_u32_array: ranges: ofnode_read_bool: bootph-all: true
>      ofnode_read_bool: bootph-all: true
>      ofnode_read_bool: bootph-all: false
>      …
> 
> This goes on for several screen pages, and clutters the usual output.
> I first thought I messed up CONFIG_LOGLEVEL or CONFIG_LOG, but no.
> All I had done was setting CONFIG_DM_WARN …
> 
> Am Tue, Jun 11, 2024 at 03:04:26PM +0200 schrieb Quentin Schulz:
>> From: Quentin Schulz <quentin.schulz at cherry.de>
>>
>> Prior to that, seeing the debug() messages required to enable DM_DEBUG
>> which defines DEBUG (and then _DEBUG) which in turn makes failing
>> assert() calls reset U-Boot which isn't necessarily what is desired.
>>
>> Instead, let's migrate to dm_warn which is using log_debug when unset or
>> log_warn when set.
>>
>> While at it, reword the DM_DEBUG symbol in Kconfig to explain what it
>> now actually does.
> 
> CONFIG_DM_WARN currently reads like this:
> 
>      Enable this to see warnings related to driver model.
> 
>      Warnings may help with debugging, such as when expected devices do
>      not bind correctly. If the option is disabled, dm_warn() is compiled
>      out - it will do nothing when called.
> 
> Instead of just useful warnings, users get debug messages all over the
> place now.  Is this actually intended behaviour?  Can this be fixed
> before v2024.10 release please?
> 

There are basically less than 3 working days left before v2024.10 is 
released and I'm inclined to say this is annoying rather than a bug, so 
I am not entirely sure this will 1) make it in time if we agree on a fix 
(needs to include review process in those 3 working days) 2) be 
acceptable for a late addition in the release cycle. Let's try though, 
maybe we can figure something out.

Enabling DM_WARN actually changes the loglevel of dm_warn calls from 
debug to warning, c.f. 
https://elixir.bootlin.com/u-boot/v2024.07/source/include/dm/util.h#L11

There seems to be no available dm-specific log function other than 
dm_warn at the moment.

The issue I had was that in order to be able to see those messages, I 
had to to select DM_DEBUG, which does much more than just enabling the 
debug log level to be printed and eventually makes my boot unsuccessful 
(see original commit message), which is not acceptable :)

Can you explain what you're trying to achieve with DM_WARN enabled so we 
have some idea how to properly fix address your concern?

In the short term, i guess we could simply define a dm_dbg macros which does
log(LOGC_DM, LOGL_DEBUG, ##fmt)
which would also replace those instances of log(LOGC_DM, LOGL_DEBUG, in 
drivers/core/uclass.c.

However this means that all those messages would only be available if we 
reach the global log level to debug, which is very verbose. I have not 
looked deeply into all those messages and their contexts and wouldn't be 
able to quickly differentiate a debug message from a warn message, so 
replacing only some of them is not a small thing to do and is error prone.

I guess what we could do is have some sort of kconfig option for log 
level per logging category? Or in some way define log filters at compile 
time?

I'm not entirely sure how to go forward with this.

[...]

>> @@ -508,17 +509,17 @@ int of_read_u16(const struct device_node *np, const char *propname, u16 *outp)
>>   {
>>   	const __be16 *val;
>>   
>> -	debug("%s: %s: ", __func__, propname);
>> +	dm_warn("%s: %s: ", __func__, propname);
> 
> This is no warning at all.  And there are tons of those changed by
> this patch.  It ended up in master as 6afdb1585112 ("dm: core: migrate
> debug() messages to use dm_warn") by the way.  Please review again and
> assign reasonable log levels for all converted messages, otherwise
> the destinction between DM_WARN and DM_DEBUG is useless?
> 

They are not exactly related, that's the issue. DM_DEBUG is not about 
the log level, it's about enabling all debug functionalities (of which 
is enabling the debug() calls), which renders the boot unsuccessful on 
my machine (see original commit message).

The second issue is, we could assign different log levels for DM, but 
they would be printed only if the global log level would be raised above 
the level of said DM log message's level. This means to see those I 
would need to see ALL debug messages using the logging framework. I 
think something more finegrained would be much more useful, but that's 
also not a 5min thing to do I guess.

Thank you for testing an RC though and filing a report, not many people 
do (me included) and we end up fixing a lot of stuff in the early days 
of a new release which is not the ideal workflow :)

Cheers,
Quentin