Logging: mechanisms and best practices

Logging: mechanisms and best practices

[Darren Hart]

In trying to add some checkpoint logging to the kernel recipes, I wanted
to understand the proper mechanisms and best practices for logging with
bitbake recipes.

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.

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.

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.

A similar variable "BBDEBUG" exists. It can be set in local.conf (the
sample suggests "yes" as a value). This has zero effect from what I can
tell. Setting BBDEBUG in the environment is used in the same way as
-D[D[D]], and if set to "yes" will cause bitbake to error out trying to
case "yes" to an integer.

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.

Would people consider the following to be appropriate:

o Remove BBDEBUG from local.conf.sample as it appears not be used.
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.
o Remove OEDEBUG as it doesn't seem to fit with the current BBDEBUG,
  -D[D[D]] mechanisms nor with the expectation that all debug statements
  get sent to the logs.

Thoughts?

-- 
Darren Hart
Intel Open Source Technology Center
Yocto Project - Linux Kernel

Re: Logging: mechanisms and best practices

[Chris Larson]

On Thu, Apr 21, 2011 at 4:53 PM, Darren Hart <dvhart@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.

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

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

> 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.  We can
programmatically check the bitbake debugging level from ${@}.  E.g.:

if ${@['false', 'true'][bb.msg.debug_level['default']]}; then
  echo "DEBUG: " "$@"
fi

> o Remove OEDEBUG as it doesn't seem to fit with the current BBDEBUG,
>  -D[D[D]] mechanisms nor with the expectation that all debug statements
>  get sent to the logs.

Agreed.
-- 
Christopher Larson
clarson at kergoth dot com
Founder - BitBake, OpenEmbedded, OpenZaurus
Maintainer - Tslib
Senior Software Engineer, Mentor Graphics

Re: Logging: mechanisms and best practices

[Darren Hart]

On 04/21/2011 05:09 PM, Chris Larson wrote:
> On Thu, Apr 21, 2011 at 4:53 PM, Darren Hart <dvhart@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.


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


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


> 
>> o Remove OEDEBUG as it doesn't seem to fit with the current BBDEBUG,
>>  -D[D[D]] mechanisms nor with the expectation that all debug statements
>>  get sent to the logs.
> 
> Agreed.

Thanks for the review and insight Chris!

-- 
Darren Hart
Intel Open Source Technology Center
Yocto Project - Linux Kernel

Re: Logging: mechanisms and best practices

[Chris Larson]

On Thu, Apr 21, 2011 at 9:23 PM, Darren Hart <dvhart@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@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