I'm just an idiot when it comes logging

[olsongt]

I'm trying to be a good boy and use the logging module but it's
behaving rather counter-intuitively. I've posted a simplified test
script below.

To summarize, I've set the basic config to only log root level messages
with >= ERROR level. I've created another named logger that logs on
info level. I've set it up so it just shows the message text without
"INFO:: logger:" boilerplate.

The way I see things, when I call otherLogger.info, it should propogate
the message to the root logger, but the root logger should discard it
since it is at ERROR level.

Could someone explain what I'm not getting?

-Grant

###
### logging_test.py
###

import logging

logging.basicConfig(level=logging.ERROR)

root = logging.getLogger('')

otherLogger = logging.getLogger("logger")
otherLogger.setLevel(logging.INFO)

console = logging.StreamHandler()
console.setLevel(logging.INFO)
formatter = logging.Formatter("%(message)s")
console.setFormatter(formatter)

otherLogger.addHandler(console)

root.info("Shouldn't print") # lower level
root.error("Should Print") #higher level

otherLogger.info("Should only print once")

root.info("Shouldn't print") # lower level

[Dennis Lee Bieber]

On 20 Mar 2005 14:25:20 -0800, ol*****@verizon.net declaimed the
following in comp.lang.python:

The way I see things, when I call otherLogger.info, it should propogate
the message to the root logger, but the root logger should discard it
since it is at ERROR level.
Create ONE logger, but give it BOTH handlers, with each handler
having different levels?

I'm not fully up on the permutations -- my usage is with one
logger, a file handler, and a stream(console) handler, so the console
only sees warning and above, while the more permanent file also captures
tracking info.

-- ================================================== ============ <
wl*****@ix.netcom.com | Wulfraed Dennis Lee Bieber KD6MOG <
wu******@dm.net | Bestiaria Support Staff <
================================================== ============ <
Home Page: <http://www.dm.net/~wulfraed/> <
Overflow Page: <http://wlfraed.home.netcom.com/> <

[Vinay Sajip]

<olsongt <at> verizon.net> writes:

I'm trying to be a good boy and use the logging module but it's
behaving rather counter-intuitively. I've posted a simplified test
script below.

To summarize, I've set the basic config to only log root level messages
with >= ERROR level. I've created another named logger that logs on
info level. I've set it up so it just shows the message text without
"INFO:: logger:" boilerplate.

The way I see things, when I call otherLogger.info, it should propogate
the message to the root logger, but the root logger should discard it
since it is at ERROR level.

Could someone explain what I'm not getting?

-Grant

The way it works is: when you log to a logger, the event level is checked
against the logger. If the event should be logged (event level >= logger level)
then the event is passed to the handlers configured for that logger, and (while
the logger's propagate attribute is true - the default - passed to handlers
configured for loggers higher up the hierarchy. In your case, this inlcudes the
root logger's handlers.

Note that if you don't set a level on a logger, then the hierarchy is searched
until a level is found. That becomes the effective level for the logger.

Handlers normally process all events passed to them, but you can set a level on
a handler to get it to drop events below a certain threshold. Since you haven't
done this, you will see an INFO message appear even though the root logger's
level is set to ERROR. (This would only affect logging calls to the root logger).

Rule of thumb: Set levels on handlers only when you need them, not as common
practice. If you don't want to see info messages from otherLogger, set its level
to > INFO.

Vinay Sajip

[olsongt]

Vinay Sajip wrote:

<olsongt <at> verizon.net> writes:
Handlers normally process all events passed to them, but you can set a level on a handler to get it to drop events below a certain threshold. Since you haven't done this, you will see an INFO message appear even though the root logger's level is set to ERROR. (This would only affect logging calls to the root logger).
Rule of thumb: Set levels on handlers only when you need them, not as common practice. If you don't want to see info messages from otherLogger, set its level to > INFO.

Vinay Sajip

Thanks Vinay,

By adding a handler with a level of ERROR I fixed my problem. Things
are starting to make sense. I just feel like a logger should filter
out any messages below its error level instead of sending them to its
handlers. But that is obviously not the case. I just need to get used
to it.

-Grant