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

[Quentin Schulz]

Hi Alexander,

On 10/2/24 11:51 AM, Alexander Dahl wrote:
> Hello Quentin,
> 
> thanks for you quick reply, see my remarks below.
> 
> Am Wed, Oct 02, 2024 at 11:25:38AM +0200 schrieb 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>

[...]

>> 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 :)
> 
> It just adds -DDEBUG to driver core cflags, so DEBUG is defined in
> preprocessor.  What you call "much more" are only implications from
> defining DEBUG, right?
> 

Correct.

> You wrote in your commit message assert() calls fail.  In my
> understanding those should not fail, and I would look to fix things
> leading to failed assertions.  IIRC standard C lib help texts say,
> assert() is only recommended for helping programmers finding bugs,
> because it's a noop in non-debug code, which would just hide problems
> and making things blow up elsewhere.  IMHO if code fails due to
> assert() you have some serious problems you should debug, not "solve"
> it by disabling debug.  In other words: your boot should also be
> successful with DEBUG/assert() enabled, shouldn't it?
> 

That's probably true. But I want to avoid the situation Hal from Malcolm 
in the Middle find himself in when trying to fix a light bulb 
(https://youtu.be/AbSehcT19u0). If I want to debug asserts, I will 
define DEBUG and start looking at those. If I want to see debug messages 
from DM, I want to see those, not that suddenly I cannot even boot 
anymore (which may make debugging impossible if the assert fails before the

>> 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?
> 
> The help text promises warnings I wanted to see in my own drivers or
> drivers I patched (very few), so I don't mess up things accidentally.
> Up to 2024.07 this seemed to work fine.
> 

Is it possible dm_warn is being abused as a debug tool here rather than 
defining a logging category for those drivers at a logging level that 
you'd find appropriate?

You could use log_* functions and define the LOG_CATEGORY in your 
driver(s), but... we would still have the issue with global log level if 
you only wanted to raise the log level for one particular driver. I 
guess this could be done by unsetting and resetting _LOG_MAX_LEVEL to 
the level you want, in your own driver? That's as hackish as setting 
DEBUG in the end :)

Are you really trying to keep track of DM core messages related to your 
driver(s)?

>> 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.
>>

@Simon, do you have something you could recommend or some idea in mind?

>> [...]
> 
> Not sure either.  I certainly won't mess with driver core.  My
> short-term solution will be to disable CONFIG_DM_WARN for now.
> 

I would see DM_WARN as a debugging option and would do the same.

>>
>>>> @@ -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.
> 
> Isn't the logging framework capable of this already?  TBH I usually
> add '#define DEBUG' to modules I want to see all messages for, and
> remove that again when done with whatever the current task is.  DM
> just makes this easier simply by hooking it to Kconfig.
> 

I believe adding DEBUG in DM core would result in the same thing as 
there are many asserts there in addition to the debug messages :)

The logging framework is probably capable of doing this through filters 
yes, though the documentation specifies how to define those filters at 
runtime, which is likely too late for debugging drivers?

Cheers,
Quentin