Logging oddity: handlers mandatory in every single logger?

[Masklinn]

When trying to load the following config file, I get an error ``ConfigParser.NoOptionError: No option 'handlers' in section: 'logger_0'`` (in both Python 2.6.4 and Python 3.1.1 on OSX, obviously ConfigParser is spelled configparser in 3.1):

[loggers]
keys=root,0
[handlers]
keys=console
[formatters]
keys=simple
[logger_root]
handlers=console
[logger_0]
level=DEBUG
qualname=0
[handler_console]
class=StreamHandler
formatter=simple
args=()
[formatter_simple]
format=%(asctime)s:%(levelname)-8s:%(name)s::%(message)s

the goal is simply to have a logging level different on ``0`` than it is on ``root``, but to get it I have to include a handler on ``0`` and stop propagation (or messages are displayed on both root and 0).

Do note that this behavior (of mandating handlers) does *not* happen when loggers are configured programmatically.

Should this be considered a bug? Worthy of opening a request on the tracker?

And while I'm at it, a few other oddities/annoyances I noticed in logging:

* have to specify the `root` logger in loggers/keys, even though it's mandatory to configure the root logger, or I get the following error::

Traceback (most recent call last):
File "test.py", line 6, in <module>
logging.config.fileConfig('logging.conf')
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.1/lib/python3.1/logging/config.py", line 82, in fileConfig
_install_loggers(cp, handlers, disable_existing_loggers)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.1/lib/python3.1/logging/config.py", line 183, in _install_loggers
llist.remove("root")
ValueError: list.remove(x): x not in list

* the ``args`` option is required when defining a handler, even in the example above where the handler doesn't take any argument (mandatory ones, anyway)

* Logger.log() doesn't take level names, only numerical levels, even after having called ``addLevelName``. This makes logging with custom levels much less clear as one has to write something along the lines of ``logging.log(100, 'Houston, we have a problem')`` instead of the clearer ``logging.log('PANTS_ON_FIRE', 'Houston, we have a problem')``. Note that since the introduction of _checkLevel fixing that is trivial:

diff -r dafc54104884 Lib/logging/__init__.py
--- a/Lib/logging/__init__.py Sun Jan 31 14:17:25 2010 +0100
+++ b/Lib/logging/__init__.py Mon Feb 01 22:21:03 2010 +0100
@@ -1146,13 +1146,14 @@

logger.log(level, "We have a %s", "mysterious problem", exc_info=1)
"""
- if not isinstance(level, int):
+ try:
+ rv = _checkLevel(level)
+ except (TypeError, ValueError):
if raiseExceptions:
- raise TypeError("level must be an integer")
- else:
- return
- if self.isEnabledFor(level):
- self._log(level, msg, args, **kwargs)
+ raise
+
+ if self.isEnabledFor(rv):
+ self._log(rv, msg, args, **kwargs)

def findCaller(self):
"""

[Jean-Michel Pichavant]

Post by Masklinn
[loggers]
keys=root,0
[handlers]
keys=console
[formatters]
keys=simple
[logger_root]
handlers=console
[logger_0]
level=DEBUG
qualname=0
[handler_console]
class=StreamHandler
formatter=simple
args=()
[formatter_simple]
format=%(asctime)s:%(levelname)-8s:%(name)s::%(message)s
the goal is simply to have a logging level different on ``0`` than it is on ``root``, but to get it I have to include a handler on ``0`` and stop propagation (or messages are displayed on both root and 0).
Do note that this behavior (of mandating handlers) does *not* happen when loggers are configured programmatically.
Should this be considered a bug? Worthy of opening a request on the tracker?
File "test.py", line 6, in <module>
logging.config.fileConfig('logging.conf')
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.1/lib/python3.1/logging/config.py", line 82, in fileConfig
_install_loggers(cp, handlers, disable_existing_loggers)
File "/opt/local/Library/Frameworks/Python.framework/Versions/3.1/lib/python3.1/logging/config.py", line 183, in _install_loggers
llist.remove("root")
ValueError: list.remove(x): x not in list
* the ``args`` option is required when defining a handler, even in the example above where the handler doesn't take any argument (mandatory ones, anyway)

To add a custom level, I would proceed that way:

logging.ALERT = 45
logging.addLevelName(logging.ALERT, 'ALERT !!')
logging.getLogger().log(logging.ALERT, 'test')

Passing a string to the log method as you did is incorrect.


Regarding your first point, I guess it's anti pattern. One way to do it:
1/ Configure the root logger with the lowest value 0, so the root logger
does not filter any level.
2/ Configure each of your logger with the correct level

That way you can configure your '0' logger as you (badly :o)) named it
with one level, and configure a potential '1' logger with another level.
Don't bother with propagation. That way you won't need to duplicate your
handlers on every logger.

JM

[Masklinn]

Post by Jean-Michel Pichavant
logging.ALERT = 45
logging.addLevelName(logging.ALERT, 'ALERT !!')
logging.getLogger().log(logging.ALERT, 'test')
Passing a string to the log method as you did is incorrect.

I know it's currently incorrect. My point was more along the line that there was *no reason* for it to be incorrect. logging already contains all the tools for log('PANTS_ON_FIRE') to be allowed

Post by Jean-Michel Pichavant
1/ Configure the root logger with the lowest value 0, so the root logger
does not filter any level.
2/ Configure each of your logger with the correct level
That way you can configure your '0' logger as you (badly :o)) named it
with one level, and configure a potential '1' logger with another level.
Don't bother with propagation. That way you won't need to duplicate your
handlers on every logger.

re logger 0, no need for complex name for a test case (and it allowed me to create easy-to-remember 0.1 and 0.1.2 if needed)

Re your answer, from what I understand you want the root logger to NOTSET and then each child logger with its correct level? But that's not a solution, each and every level will *still* require a handler explicitly configured on it. That's in fact very much my issue: logging refuses that a logger be handler-less in a config file, it's mandatory to configure a handler any time a logger is configured.

[Jean-Michel Pichavant]

Post by Masklinn

Post by Jean-Michel Pichavant
logging.ALERT = 45
logging.addLevelName(logging.ALERT, 'ALERT !!')
logging.getLogger().log(logging.ALERT, 'test')
Passing a string to the log method as you did is incorrect.

I know it's currently incorrect. My point was more along the line that there was *no reason* for it to be incorrect. logging already contains all the tools for log('PANTS_ON_FIRE') to be allowed

The reason is that log takes an *int* as first argument that defines the
logging level. You gave a string. So There is definitely a reason for it
to be incorrect.

Post by Masklinn

Post by Jean-Michel Pichavant
1/ Configure the root logger with the lowest value 0, so the root logger
does not filter any level.
2/ Configure each of your logger with the correct level
That way you can configure your '0' logger as you (badly :o)) named it
with one level, and configure a potential '1' logger with another level.
Don't bother with propagation. That way you won't need to duplicate your
handlers on every logger.

re logger 0, no need for complex name for a test case (and it allowed me to create easy-to-remember 0.1 and 0.1.2 if needed)
Re your answer, from what I understand you want the root logger to NOTSET and then each child logger with its correct level? But that's not a solution, each and every level will *still* require a handler explicitly configured on it. That's in fact very much my issue: logging refuses that a logger be handler-less in a config file, it's mandatory to configure a handler any time a logger is configured.

the field handlers must be defined even if empty.

[loggers]
keys=root,0,1

[handlers]
keys=console

[formatters]
keys=simple

[logger_root]
level=DEBUG
handlers=console

[logger_1]
level=INFO
qualname=1
handlers=

[logger_0]
level=DEBUG
qualname=0
handlers=

[handler_console]
class=StreamHandler
formatter=simple
args=()

[formatter_simple]
format=%(asctime)s:%(levelname)-8s:%(name)s::%(message)s


import logging; import logging.config
logging.config.fileConfig("log.config")
l1 = logging.getLogger("1")
l0 = logging.getLogger("0")
l1.debug('I am l1')
...
l0.debug('I am l0')
... 2010-02-02 17:48:55,710:DEBUG :0::I am l0

JM

[Masklinn]

Post by Masklinn

Post by Jean-Michel Pichavant
logging.ALERT = 45
logging.addLevelName(logging.ALERT, 'ALERT !!')
logging.getLogger().log(logging.ALERT, 'test')
Passing a string to the log method as you did is incorrect.

I know it's currently incorrect. My point was more along the line that there was *no reason* for it to be incorrect. logging already contains all the tools for log('PANTS_ON_FIRE') to be allowed

The reason is that log takes an *int* as first argument that defines the logging level. You gave a string. So There is definitely a reason for it to be incorrect.

That's not a reason, that's just what currently happens. I know it doesn't work, and I know why, I went and checked the code. But there's no fundamental reason why you couldn't use a level *name* instead of a level code. And indeed, in most parts of logging you can (including but not limited to the configuration of handlers and loggers)

Post by Masklinn

Post by Jean-Michel Pichavant
1/ Configure the root logger with the lowest value 0, so the root logger does not filter any level.
2/ Configure each of your logger with the correct level
That way you can configure your '0' logger as you (badly :o)) named it with one level, and configure a potential '1' logger with another level. Don't bother with propagation. That way you won't need to duplicate your handlers on every logger.

re logger 0, no need for complex name for a test case (and it allowed me to create easy-to-remember 0.1 and 0.1.2 if needed)
Re your answer, from what I understand you want the root logger to NOTSET and then each child logger with its correct level? But that's not a solution, each and every level will *still* require a handler explicitly configured on it. That's in fact very much my issue: logging refuses that a logger be handler-less in a config file, it's mandatory to configure a handler any time a logger is configured.

the field handlers must be defined even if empty.

Ah, interesting, I didn't think it could be defined as empty.

Which makes the requirement to have an empty ``handler`` completely nonsensical, doesn't it?

[Jean-Michel Pichavant]

Post by Masklinn

The reason is that log takes an *int* as first argument that defines the logging level. You gave a string. So There is definitely a reason for it to be incorrect.

That's not a reason, that's just what currently happens. I know it doesn't work, and I know why, I went and checked the code. But there's no fundamental reason why you couldn't use a level *name* instead of a level code. And indeed, in most parts of logging you can (including but not limited to the configuration of handlers and loggers)

You don't neeed to check the code for that ! It is written in the
documentation. The logging module designer choose to ask for a level,
not a level name, possibly because 2 different levels can have the same
name.

Post by Masklinn

the field handlers must be defined even if empty.

Ah, interesting, I didn't think it could be defined as empty.
Which makes the requirement to have an empty ``handler`` completely nonsensical, doesn't it?

'completeley nonsensical' is overstating. It make sense to state that
your handler list is empty, when it is empty. Having no field at all
could possibly mean the same, but it's often better that have one
consisten way to interface with a module.


JM

[Masklinn]

Post by Masklinn

The reason is that log takes an *int* as first argument that defines the logging level. You gave a string. So There is definitely a reason for it to be incorrect.

That's not a reason, that's just what currently happens. I know it doesn't work, and I know why, I went and checked the code. But there's no fundamental reason why you couldn't use a level *name* instead of a level code. And indeed, in most parts of logging you can (including but not limited to the configuration of handlers and loggers)

You don't neeed to check the code for that ! It is written in the documentation. The logging module designer choose to ask for a level, not a level name, possibly because 2 different levels can have the same name.

Nope, 2 different levels cannot have the same name: levels are currently stored in a dict of string:level and level:string, so you can't have 2 names for the same level, and you can't have 2 levels with the same name either.

Post by Masklinn

the field handlers must be defined even if empty.

Ah, interesting, I didn't think it could be defined as empty.
Which makes the requirement to have an empty ``handler`` completely nonsensical, doesn't it?

'completeley nonsensical' is overstating. It make sense to state that your handler list is empty, when it is empty.

Programmatically, that's implied in the fact that you aren't specifying it. Why wouldn't it be in the config file? Why the asymetry here?

[Jean-Michel Pichavant]

Post by Masklinn

You don't neeed to check the code for that ! It is written in the documentation. The logging module designer choose to ask for a level, not a level name, possibly because 2 different levels can have the same name.

Nope, 2 different levels cannot have the same name: levels are currently stored in a dict of string:level and level:string, so you can't have 2 names for the same level, and you can't have 2 levels with the same name either.

import logging
logging.addLevelName(5, 'test')
logging.addLevelName(6, 'test')

logging._levelNames
{0: 'NOTSET',
5: 'test',
6: 'test',
10: 'DEBUG',
20: 'INFO',
30: 'WARNING',
40: 'ERROR',
50: 'CRITICAL',
'CRITICAL': 50,
'DEBUG': 10,
'ERROR': 40,
'INFO': 20,
'NOTSET': 0,
'WARN': 30,
'WARNING': 30,
'test': 6}

now quoting the doc:

logging.addLevelName(/lvl/, /levelName/)
Associates level /lvl/ with text /levelName/ in an internal
dictionary, which is *used to map numeric levels to a textual
representation*, for example when a Formatter
<http://docs.python.org/library/logging.html#logging.Formatter>
formats a message. This function can also be used to define your own
levels. The only constraints are that all levels used must be
registered using this function, levels should be positive integers
and they should increase in increasing order of severity.


int -> string is the public association
string- > int is an internal hack to map easilty map Level name to their
int identifier. This is used for the config file, where you specify a
string not an int (you vrite level=DEBUG, not level=10)

Look at the builtin WARNING & WARN level, two different names for the
same level.

In any case, you have to trust the documentation and public interface
signature. Introspecting the code can be misleading. Now I better
understand your initial concern.

Post by Masklinn

Post by Masklinn

Post by Jean-Michel Pichavant
the field handlers must be defined even if empty.

Ah, interesting, I didn't think it could be defined as empty.
Which makes the requirement to have an empty ``handler`` completely nonsensical, doesn't it?

'completeley nonsensical' is overstating. It make sense to state that your handler list is empty, when it is empty.

Programmatically, that's implied in the fact that you aren't specifying it. Why wouldn't it be in the config file? Why the asymetry here?

Note how progammatically the list of handlers is set to an empty list.
The attribute handlers is always set, so the config file field shall be :o)

In [11]: logger = logging.getLogger('test')

In [12]: logger.handlers
Out[12]: []



JM

[Vinay Sajip]

On Feb 3, 11:36?am, Masklinn <maskl... at masklinn.net> wrote:

Well, Xavier,

I would be the first to agree that the existing logging configuration
API is not ideal. There are a number of reasons for the current
ConfigParser schema used (e.g. an old GUI for configuring logging,
which was there before the logging package was added to Python, but
which was not brought across). However, there is no point in
nitpicking over the particular shortcomings you've focused on, unless
of course you've run out of bikesheds to paint ;-)

Particularly as I've just received the good news from Guido van Rossum
that PEP 391 (Dictionary-Based Configuration For Logging) has been
accepted, and my aim is to get it into Python 2.7 and Python 3.2.

Now, PEP 391 was announced on python-list and python-dev in October
2009, so plenty of people have had an opportunity to comment on it.
Going forwards, and over time, I would hope that this configuration
scheme will supplant the ConfigParser-based approach, and so I don't
think there's much need to tinker with that API.

Onwards, upwards, ever forwards :-)

Regards,

Vinay Sajip