logging

[Baurzhan Ismagulov]

Hello all,

I want that each module has its own logger. I've defined the following
config file:

[formatters]
keys=f01

[handlers]
keys=console

[loggers]
keys=root,l01

[formatter_f01]
format=%(name)s: %(message)s

[handler_console]
class=StreamHandler
args=[]
formatter=f01

[logger_root]
level=CRITICAL
handlers=console

[logger_l01]
level=DEBUG
qualname=l01
handlers=console


I use it like this:

import logging
import logging.config

logging.config.fileConfig('a.conf')
log = logging.getLogger('l01')
log.debug('zzz')


I want logger_root to go to /dev/null, so I've configured it with level
CRITICAL. My understanding is that in this way debug messages are not
printed on logger_root's handler. However, running the program results
in the message being printed twice. What is the problem?


Thanks in advance,
Baurzhan.

 

[Vinay Sajip]

Hello all,

I want that each module has its own logger. I've defined the following
config file:

[logger_root]
level=CRITICAL
handlers=console

[logger_l01]
level=DEBUG
qualname=l01
handlers=console

I want logger_root to go to /dev/null, so I've configured it with level
CRITICAL. My understanding is that in this way debug messages are not
printed on logger_root's handler. However, running the program results
in the message being printed twice. What is the problem?

You've defined the handler against both the root logger and l01. You
only need it configured for the root logger - events passed to l01 will
be passed to all handlers up the hierarchy. So remove the
"handlers=console" line from [logger_l01] and it should print the
message just once.

Vinay Sajip

 

[Baurzhan Ismagulov]

Hello Vinay,

[logger_root]
level=CRITICAL
handlers=console

[logger_l01]
level=DEBUG
qualname=l01
handlers=console

I want logger_root to go to /dev/null, so I've configured it with level
CRITICAL. My understanding is that in this way debug messages are not
printed on logger_root's handler. However, running the program results
in the message being printed twice. What is the problem?

You've defined the handler against both the root logger and l01. You
only need it configured for the root logger - events passed to l01 will
be passed to all handlers up the hierarchy. So remove the
"handlers=console" line from [logger_l01] and it should print the
message just once.

Thanks for the idea! I think this should work for the example I sent.
However, I have more than one module, and I want to log only l01. How
can I do that?

Thanks in advance,
Baurzhan.

 

[Vinay Sajip]

Thanks for the idea! I think this should work for the example I sent.
However, I have more than one module, and I want to log only l01. How
can I do that?

I don't know what your logger hierarchy looks like: you could perhaps
log to child loggers of l01 ("l01.XXX"), or set all other loggers you
use to have a CRITICAL level, or filter them using a filter which
filters out everything.

Regards,

Vinay

 

[Baurzhan Ismagulov]

Hello Vinay,

I don't know what your logger hierarchy looks like: you could perhaps
log to child loggers of l01 ("l01.XXX"), or set all other loggers you
use to have a CRITICAL level, or filter them using a filter which
filters out everything.

Ok, here is my hierarchy:

[formatters]
keys=f01

[handlers]
keys=console

[loggers]
keys=root,l01,l02

[formatter_f01]
format=%(name)s: %(message)s

[handler_console]
class=StreamHandler
args=[]
formatter=f01

[logger_root]
level=CRITICAL
handlers=console

[logger_l01]
level=DEBUG
qualname=l01
handlers=console

[logger_l02]
level=CRITICAL
qualname=l02
handlers=console


The program is:

import logging
import logging.config

logging.config.fileConfig('a.conf')
log1 = logging.getLogger('l01')
log2 = logging.getLogger('l02')
log1.debug('zzz')
log2.debug('qqq')


With the config above, I expect that zzz gets printed, and qqq doesn't.
When I run the script, zzz is printed twice, and qqq isn't. I want that
zzz is printed once. How do I do that? I can add a filter if this can't
be done otherwise, however, I'm at the moment reluctant to do that since
I don't see why CRITICAL for root passes zzz through and drops qqq
correctly for l02.


Thanks in advance,
Baurzhan.

 

[Vinay Sajip]

Hello Vinay,
Ok, here is my hierarchy:
[snip]

[handlers]
keys=console [snip]
[logger_root]
level=CRITICAL
handlers=console

[logger_l01]
level=DEBUG
qualname=l01
handlers=console

[logger_l02]
level=CRITICAL
qualname=l02
handlers=console

[snip]

With the config above, I expect that zzz gets printed, and qqq doesn't.
When I run the script, zzz is printed twice, and qqq isn't. I want that
zzz is printed once. How do I do that? I can add a filter if this can't
be done otherwise, however, I'm at the moment reluctant to do that since
I don't see why CRITICAL for root passes zzz through and drops qqq
correctly for l02.

Did you try removing the handler from l01, as I suggested in an earlier
reply? The config above still has the console handler attached to root,
l01 and l02. The reason that zzz is printed twice is that when a logger
decides to process an event, it is passed to handlers attached to
ancestor loggers (unless propagate is set to 0 - but this is not the
normal situation). So, log1 is deciding to process the event (based on
the level), and passing it to its own handlers (l01->console) and then
to its ancestor loggers' handlers (root->console). Remove the handlers
from l01 and l02 and try again.

 

[ibr]

Hello Vinay,

[snip]

[handlers]
keys=console [snip]

[logger_root]
level=CRITICAL
handlers=console

[logger_l01]
level=DEBUG
qualname=l01
handlers=console

[logger_l02]
level=CRITICAL
qualname=l02
handlers=console

[snip] ....
When I run the script, zzz is printed twice, and qqq isn't. I want that
zzz is printed once.

....
Did you try removing the handler from l01, as I suggested in an earlier
reply?

I had removed the whole line, and it complained about the missing
handlers line. Now I've tried with 'handlers=', this seems to work.
Thanks much!

The reason that zzz is printed twice is that when a logger decides to
process an event, it is passed to handlers attached to ancestor
loggers (unless propagate is set to 0 - but this is not the normal
situation). So, log1 is deciding to process the event (based on the
level), and passing it to its own handlers (l01->console) and then to
its ancestor loggers' handlers (root->console).

Hmm, log1 decides once whether to print an event, and after that it gets
printed in log1 and all its ancestors, regardless of their level? I find
this quite counter-intuitive. I'd instead expect that each logger
decides whether to print an event according to its own level. Could you
give an example why one would want the python behavior?


With kind regards,
Baurzhan.

 

[Vinay Sajip]

Hello Vinay,

Hmm, log1 decides once whether to print an event, and after that it gets
printed in log1 and all its ancestors, regardless of their level? I find
this quite counter-intuitive. I'd instead expect that each logger
decides whether to print an event according to its own level. Could you
give an example why one would want the python behavior?

Loggers are hierarchical for a reason - not just randomly named
channels. Just as it is generally useful to develop a system by
modularising it into subsystems, packages, modules, etc. so it is
useful when logging to follow a parallel hierarchy. The audiences for
the logging events are orthogonal to the events themselves, and the way
the logging module is organised reflects good practice as determined by
practical experience over a period of time. The approach you're
questioning is not specific to Python - log4j (which inspired Python's
logging), and the logging built into Java 1.4, also work this way.
Practically, this makes configuration a lot simpler; if I want to log
everything to console, I just attach a handler to the root logger, and
I never have to worry about attaching to every single logger. (Logger
names are generally not cast in stone - I might break down a module's
logic into smaller pieces and thus introduce new logger names to
describe events in the refactored module. I certainly don't want to
change my logging configuration every time I refactor my code.)

May I suggest you review the log4j documentation to get a better
exposition of the principles which govern the design of such logging
systems.

 

[Baurzhan Ismagulov]

Hello Vinay,

Loggers are hierarchical for a reason - not just randomly named
channels. ...

Thanks for the explanation! Please note that I am not questioning the
usefulness of hierarchical logging -- I think it's a Good Thing. What I
can't understand is the motivation for the single place of decision
whether a message should be printed ("is enabled" in log4j terms) or
not.

Consider the following scenario: root is CRITICAL, l01 is DEBUG, a debug
message is logged on l01. l01 decides that the message should be
printed, and _both_ root and l01 print it. Now, it is good that the
message is propagated to root, but why doesn't root decide for itself
whether to print it or not?

For instance, I log root to syslog and have only critical messages
there. I log l01 to console to debug. I want that my message to l01 is
not printed by root since its level is CRITICAL. This is why I want that
each logger re-evaluates the message level for itself. Could you perhaps
give a useful example why one could want loggers to decide once?


And another thing I couldn't find how to do: I want to have several
debug levels. I can log messages without problems, but numeric values in
the configuration file cause error messages during
logging.config.fileConfig. Can I specify numeric values in the config
file?


With kind regards,
Baurzhan.

 

[Vinay Sajip]

Hello Baurzhan,

Consider the following scenario: root is CRITICAL, l01 is DEBUG, a debug
message is logged on l01. l01 decides that the message should be
printed, and _both_ root and l01 print it. Now, it is good that the
message is propagated to root, but why doesn't root decide for itself
whether to print it or not?

It's not propagated to the root logger (or to ancestor loggers in
general) - just to the handlers associated with ancestor loggers.

For instance, I log root to syslog and have only critical messages
there. I log l01 to console to debug. I want that my message to l01 is
not printed by root since its level is CRITICAL. This is why I want that
each logger re-evaluates the message level for itself. Could you perhaps
give a useful example why one could want loggers to decide once?

You can set levels on handlers as well as loggers. So if you add a
syslog handler to the root and set its level to CRITICAL, only CRITICAL
messages are sent to syslog.

And another thing I couldn't find how to do: I want to have several
debug levels. I can log messages without problems, but numeric values in
the configuration file cause error messages during
logging.config.fileConfig. Can I specify numeric values in the config
file?

You should use addLevelName to add custom levels. You can do e.g.

logging.MYCUSTOMLEVEL = 25
logging.addLevelName(logging.MYCUSTOMLEVEL, "MYCUSTOMLEVEL")

and then reference MYCUSTOMLEVEL in the config file.

Regards,

Vinay

 

[Baurzhan Ismagulov]

Hello Vinay,

It's not propagated to the root logger (or to ancestor loggers in
general) - just to the handlers associated with ancestor loggers. ....
You can set levels on handlers as well as loggers. So if you add a
syslog handler to the root and set its level to CRITICAL, only CRITICAL
messages are sent to syslog. ....
logging.MYCUSTOMLEVEL = 25
logging.addLevelName(logging.MYCUSTOMLEVEL, "MYCUSTOMLEVEL")

Thanks much!

With kind regards,
Baurzhan.