Two similar logging programs but different ouputs

[Disc Magnet]

I have tried writing two programs which are doing similar activities.
The little difference between the two programs is that the first one
configures logger1 using addHandler() method while the second program
configures logger1 from log.conf file.

However, the output differs for both. The first program displays
warnings from both logger1 and logger2. The second program displays
warning from logger1 only. It does not display the warning from
logger2.

Could you please help me understand this difference? Programs and
log.conf file follow:

#!/usr/bin/env python2.7

# This program prints both the warnings
import logging

# Create loggers
logger1 = logging.getLogger()
logger2 = logging.getLogger('foo.bar')

# Configure both loggers
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter('%(name)s %(levelname)s %(message)s'))
logger1.addHandler(handler)
logger2.addHandler(logging.NullHandler())

# Use both loggers
logger1.warn('warning 1')
logger2.warn('warning 2')

#----------------------------------------------------------------------

#!/usr/bin/env python2.7

# This program prints only the first warning

import logging
import logging.config

# Create loggers
logger1 = logging.getLogger()
logger2 = logging.getLogger('foo.bar')

# Configure root loggers
logging.config.fileConfig('log.conf')
logger2.addHandler(logging.NullHandler())

# Use both loggers
logger1.warn('warning 1')
logger2.warn('warning 2')

#-----------------------------------------------------------------------

"""The file 'log.conf' is as follows:

[loggers]
keys=root

[handlers]
keys=streamHandler

[formatters]
keys=simpleFormatter

[logger_root]
handlers=streamHandler

[handler_streamHandler]
class=StreamHandler
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(name)s %(levelname)s %(message)s
"""

#-----------------------------------------------------------------------

 

[Vinay Sajip]

Could you please help me understand this difference? Programs and
log.conf file follow:

The first program prints two messages because loggers pass events to
handlers attached to themselves and their ancestors. Hence, logger1's
message is printed by logger1's handler, and logger2's message is
printed by logger1's handler because it is an ancestor of logger2.

In the second case, logger foo.bar exists when fileConfig() is
called, but it is not named explicitly in the configuration. Hence,
it is disabled (as documented). Hence only logger1's message is
printed.

NullHandler is a handler which does nothing - there is no point in
adding it to a system which configures logging, and only any point in
adding it to top-level loggers of libraries which may be used when
logging is configured (also documented).

Regards,

Vinay Sajip
Regards,

Vinay Sajip

 

[Vinay Sajip]

Could you please help me understand this difference? Programs and
log.conf file follow:

The first program prints two messages because loggers pass events to
handlers attached to themselves and their ancestors. Hence, logger1's
message is printed by logger1's handler, and logger2's message is
printed by logger1's handler because logger1 is an ancestor of
logger2.

In the second case, logger foo.bar exists when fileConfig() is
called, but it is not named explicitly in the configuration. Hence,
it is disabled (as documented). Hence only logger1's message is
printed.

NullHandler is a handler which does nothing - there is no point in
adding it to a system which configures logging, and only any point in
adding it to top-level loggers of libraries which may be used when
logging is not configured by the using application (this is also
documented).

Regards,

Vinay Sajip

 

[Disc Magnet]

Thank you Vinay for the quick reply. I have a few more questions.

The first program prints two messages because loggers pass events to
handlers attached to themselves and their ancestors. Hence, logger1's
message is printed by logger1's handler, and logger2's message is
printed by logger1's handler because logger1 is an ancestor of
logger2.

In the second case, logger foo.bar exists when fileConfig() is
called,  but it is not named explicitly in the configuration. Hence,
it is disabled (as documented). Hence only logger1's message is
printed.

I couldn't find this mentioned in the documentation at:

http://docs.python.org/library/logging.config.html#configuration-file-format

Could you please tell me where this is documented?

NullHandler is a handler which does nothing - there is no point in
adding it to a system which configures logging, and only any point in
adding it to top-level loggers of libraries which may be used when
logging is not configured by the using application (this is also
documented).

Actually, I was learning how logging works with NullHandler because I
am going to use it with a library I am writing. The code that I shared
is meant for experimenting. Once, I am comfortable with the logging
API, I'll separate the code into different modules.

In the following code, foo.bar is not explicitly mentioned in the file
configuration. As per what you said, foo.bar should be disabled.
However, I get the following output:

root WARNING warning 1
foo WARNING warning 2
foo WARNING warning 2
foo.bar WARNING warning 3
foo.bar WARNING warning 3

Program and configuration file follow:

#!/usr/bin/env python2.7

# This program prints only the first warning

import logging
import logging.config

# Create loggers
logger1 = logging.getLogger()
logger2 = logging.getLogger('foo')
logger3 = logging.getLogger('foo.bar')

# Configure root loggers
logging.config.fileConfig('log.conf')
logger2.addHandler(logging.NullHandler())
logger3.addHandler(logging.NullHandler())

# Use both loggers
logger1.warn('warning 1')
logger2.warn('warning 2')
logger3.warn('warning 3')

#-----------------------------------------------------------------------

"""The file 'log.conf' is as follows:

[loggers]
keys=root,foo

[handlers]
keys=streamHandler

[formatters]
keys=simpleFormatter

[logger_root]
handlers=streamHandler

[logger_foo]
qualname=foo
handlers=streamHandler

[handler_streamHandler]
class=StreamHandler
formatter=simpleFormatter
args=(sys.stdout,)

[formatter_simpleFormatter]
format=%(name)s %(levelname)s %(message)s
"""

#-----------------------------------------------------------------------

 

[Vinay Sajip]

I couldn't find this mentioned in the documentation at:

http://docs.python.org/library/logging.config.html#configuration-file...

Could you please tell me where this is documented?

It's documented here:

http://docs.python.org/library/logging.config.html#dictionary-schema-details

(look for 'disable_existing_logger'), but having looked at it, it *is*
poorly documented and hard to find. I'll update the fileConfig section
to describe the behaviour more clearly.

In the following code, foo.bar is not explicitly mentioned in the file
configuration. As per what you said, foo.bar should be disabled.

Actually I wasn't clear enough in my earlier response. The behaviour
is that all loggers are disabled other than those explicitly named in
the configuration *and their descendants*.

I'm glad you brought these points up, they do highlight an area where
the documentation could be clearer. I'll get on it.

Regards,

Vinay Sajip