[poky] Logging: mechanisms and best practices

[Chris Larson]

On Thu, Apr 21, 2011 at 9:23 PM, Darren Hart <dvhart at linux.intel.com> wrote:
>
> On 04/21/2011 05:09 PM, Chris Larson wrote:
>> On Thu, Apr 21, 2011 at 4:53 PM, Darren Hart <dvhart at linux.intel.com> wrote:
>>>
>>> From what I could gather, the preferred method is to use the various
>>> loglevel functions from bb. ie:
>>>
>>> bb.fatal()      A fatal error, the recipe will set the error code and
>>>                abort.
>>> bb.error()      A non-fatal error. The error code is set, the build
>>>                will be marked as red in the autobuilder.
>>> bb.warn()       A non-fatal condition that could affect how things
>>>                progress.
>>> bb.debug()      One of several debug levels.
>>> bb.note()       A condition the user should be made aware of
>>> bb.plain()      typically the output of a tool, such as listtasks
>>>
>>> note and plain will go to the console and should be used extremely
>>> sparingly. debug will only go to the console with the -D[D[D]] bitbake
>>> arguments, but should always go to the logs.
>>
>> As far as I know, notes from tasks are no longer displayed with
>> knotty.  They certainly aren't in master.
>
>
> Gah, right. I knew that, got lost in maelstrom.
>
>
>>
>>> For annotating your recipe's task's logs, debug should typically be
>>> used. warn() should be used whenever possible over error() so as to not
>>> set the error code.
>>
>> Correct.
>>
>>> The above only covers the python functions in recipes. Unfortunately,
>>> many functions are bash. Most of these recipes use "echo", although
>>> there exist wrappers to echo in base.bbclass:
>>>
>>> oenote
>>> oewarn
>>> oedebug
>>> oefatal
>>>
>>> As these only wrap echo, none of them go to the console without -D[D[D]]
>>> flags. Note the absence of oeplain and oeerror. oeplain wouldn't work
>>> the same as bb.plain() as it doesn't go the console, the existing oenote
>>> has a similar problem. I've added oeerror() to my local build. oedebug()
>>> uses "clever" bash tests to check the OEDEBUG loglevel, unfortunately
>>> this causes the function to exit with a failure code when the condition
>>> is not met. I've addressed this as well. There are zero users of the oe*
>>> logging calls in "meta" but I did find several users in oe.
>>>
>>> The oe* calls depend on OEDEBUG which is not included in the environment
>>> whitelists and is not set by the -D[D[D]] arguments. Even adding it to
>>> the whitelist and my environent it wasn't accessible from the bash
>>> function. I was unable to to use oedebug() as I couldn't get the OEDEBUG
>>> value set without hardcoding it into base.bbclass.
>>
>> These are largely remnants.  I'm not opposed to having the shell
>> functions that output useful things, but at the very least we can use
>> a python snippet to check the current bitbake logging level rather
>> than relying on an old env var.  There's currently no way for shell to
>> output things to the bitbake UI's display.  In the long term, we
>> should be able to provide small command-line scripts which communicate
>> with the current running bitbake server the same way the current
>> running UI does.
>
>
> If they are remnants, would anyone object to my replacing them with:
>
> bbplain()
> bbnote()
> bbwarn()
> bbdebug()
> bberror()
> bbfatal()
>
> ?
>
> My hope is to get something working now, even if it is just to the logs,
> that we can extend the functionality of by integrating it with bitbake
> logging later - without changing the interface.

Seems reasonable to me.

>>
>>> So... before I start breaking things, I wanted to make sure I fully
>>> understand how these mechanisms are intended to be used. Also, I would
>>> very much like to see a consistent interface between bash and python
>>> fragments that have the same semantics. There are also at least two more
>>> logging mechanisms I stumbled across withing the bitbake source. One is
>>> marked deprecated, and I'm not sure how the other is meant to be used.
>>> The two I mentioned above seem to be the right ones for recipes to use.
>>
>> This is correct.  Internal bitbake code should be using the python
>> logging framework at this time.  For now, the api functions
>> bb.{error,warn,...} are correct for the metadata.
>
>
> "For now"... Do you expect to see a change here? I don't want to go off
> canonicalizing my recipes if the recipes logging API is likely to change
> significantly from what I use.

As far as I know there are no plans to change the API for recipes.  I
could see it being beneficial in certain particular cases, e.g. if one
wants to send their messages to a particular domain, but I doubt it's
worth the trouble.

>>
>>> Would people consider the following to be appropriate:
>>>
>>> o Remove BBDEBUG from local.conf.sample as it appears not be used.
>>
>> Agreed.
>>
>>> o Modify oedebug to always echo the message as all echos only go to the
>>>  logs anyway. A future change may enhance the oe* calls to print to the
>>>  console for oenote, a new oeplain, and oedebug based on -D[D[D]] and
>>>  BBDEBUG.
>>
>> This would lose us functionality unnecessarily.
>
>
> Well... right now it doesn't work at all ;-)
>
>
>> We can
>> programmatically check the bitbake debugging level from ${@}.  E.g.:
>>
>> if ${@['false', 'true'][bb.msg.debug_level['default']]}; then
>>   echo "DEBUG: " "$@"
>> fi
>
>
> The problem I have with this approach is that it limits what gets sent
> to the logs. As I understand it, the -D[D[D]] mechanism is meant to
> limit what gets sent to the console, but all debug output should go to
> the logs.
>
> So until we integrate this with the bitbake logger, I think it makes the
> most sense to just print it all to the logs.
>
> Am I off in the weeds here?

Nope, well spotted, that's an excellent point.  Better to lean toward
verbosity for useful logs.
-- 
Christopher Larson
clarson at kergoth dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Maintainer - Tslib
Senior Software Engineer, Mentor Graphics