Ñò
Ã#xPc @ s d Z d d k Z d d k Z d d k Z d d k Z d d k Z d d k Z d Z h e i d 6e i d 6e i
d 6e i d 6e i d 6e i d 6e i
d
6Z e i e i
e i e i e i
f Z d Z d „ Z d
„ Z d „ Z d „ Z d e f d „ ƒ YZ d S( s†Q
Quick Start Guide For Using This Module
=======================================
This module implements a Log Manager class which wraps the Python
logging module and provides some utility functions for use with
logging. All logging operations should be done through the
`LogManager` where available. *DO NOT create objects using the
Python logging module, the log manager will be unaware of them.*
This module was designed for ease of use while preserving advanced
functionality and performance. You must perform the following steps.
1. Import the log_manger module and instantiate *one* `LogManager`
instance for your application or library. The `LogManager` is
configured via `LogManager.configure()` whose values are
easily populated from command line options or a config file. You
can modify the configuration again at any point.
2. Create one or more output handlers via
`LogManager.create_log_handlers()` an easy to use yet powerful
interface.
3. In your code create loggers via `LogManager.get_logger()`. Since
loggers are normally bound to a class this method is optimized for
that case, all you need to do in the call ``__init__()`` is::
log_mgr.get_logger(self, True)
Then emitting messages is as simple as ``self.debug()`` or ``self.error()``
Example:
--------
::
# Step 1, Create log manager and configure it
prog_name = 'my_app'
log_mgr = LogManager(prog_name)
log_mgr.configure(dict(verbose=True))
# Step 2, Create handlers
log_mgr.create_log_handlers([dict(name='my_app stdout',
stream=sys.stdout,
level=logging.INFO),
dict(name='my_app file',
filename='my_app.log',
level=logging.DEBUG)])
# Step 3, Create and use a logger in your code
class FooBar:
def __init__(self, name):
log_mgr.get_logger(self, True)
self.info("I'm alive! %s", name)
foobar = FooBar('Dr. Frankenstein')
# Dump the log manager state for illustration
print
print log_mgr
Running the above code would produce::
: I'm alive! Dr. Frankenstein
root_logger_name: my_app
configure_state: None
default_level: INFO
debug: False
verbose: True
number of loggers: 2
"my_app" [level=INFO]
"my_app.__main__.FooBar" [level=INFO]
number of handlers: 2
"my_app file" [level=DEBUG]
"my_app stdout" [level=INFO]
number of logger regexps: 0
*Note, Steps 1 & 2 were broken out for expository purposes.* You can
pass your handler configuration into `LogManager.configure()`. The above
could have been simpler and more compact.::
# Step 1 & 2, Create log manager, and configure it and handlers
prog_name = 'my_app'
log_mgr = LogManager(prog_name)
log_mgr.configure(dict(verbose=True,
handlers = [dict(name='my_app stdout',
stream=sys.stdout,
level=logging.INFO),
dict(name='my_app file',
filename='my_app.log',
level=logging.DEBUG)])
FAQ (Frequently Asked Questions)
================================
#. **Why is this better than logging.basicConfig? The short example
for the LogManager doesn't seem much different in complexity from
basicConfig?**
* You get independent logging namespaces. You can instantiate
multiple logging namespaces. If you use this module you'll be
isolated from other users of the Python logging module avoiding
conflicts.
* Creating and initializing loggers for classes is trivial. One
simple call creates the logger, configures it, and sets logging
methods on the class instance.
* You can easily configure individual loggers to different
levels. For example turn on debuging for just the part of the
code you're working on.
* The configuration is both simple and powerful. You get many more
options than with basicConfig.
* You can dynamically reset the logging configuration during
execution, you're not forced to live with the config established
during program initialization.
* The manager optimizes the use of the logging objects, you'll
spend less time executing pointless logging code for messages
that won't be emitted.
* You can see the state of all the logging objects in your
namespace from one centrally managed location.
* You can configure a LogManager to use the standard logging root
logger and get all the benefits of this API.
#. **How do I turn on debug logging for a specific class without
affecting the rest of the logging configuration?**
Use a logger regular expression to bind a custom level to loggers
whose name matches the regexp. See `LogManager.configure()`
for details.
Lets say you want to set your Foo.Bar class to debug, then do
this::
log_mgr.configure(dict(logger_regexps=[(r'Foo\.Bar', 'debug')]))
#. **I set the default_level but all my loggers are configured
with a higher level, what happened?**
You probably don't have any handlers defined at or below the
default_level. The level set on a logger will never be
lower than the lowest level handler available to that logger.
#. **My logger's all have their level set to a huge integer, why?**
See above. Logger's will never have a level less than the level of
the handlers visible to the logger. If there are no handlers then
loggers can't output anything so their level is set to maxint.
#. **I set the default_level but all the loggers are configured
at INFO or DEBUG, what happened?**
The verbose and debug config flags set the default_level to
INFO and DEBUG respectively as a convenience.
#. **I'm not seeing messages output when I expect them to be, what's
wrong?**
For a message to be emitted the following 3 conditions must hold:
* Message level >= logger's level
* Message level >= handler's level
* The message was not elided by a filter
To verify the above conditions hold print out the log manager state
(e.g. print log_mgr). Locate your logger, what level is at? Locate
the handler you expected to see the message appear on, what level
is it?
A General Discussion of Python Logging
======================================
The design of this module is driven by how the Python logging module
works. The following discussion complements the Python Logging Howto,
fills in some missing information and covers strategies for
implementing different functionality along with the trade-offs
involved.
Understanding when & how log messages are emitted:
--------------------------------------------------
Loggers provide the application interface for logging. Every logger
object has the following methods debug(), info(), warning(), error(),
critical(), exception() and log() all of which can accept a format
string and arguments. Applications generate logging messages by
calling one of these methods to produce a formatted message.
A logger's effective level is the first explicitly set level found
when searching from the logger through it's ancestors terminating at
the root logger. The root logger always has an explicit level
(defaults to WARNING).
For a message to be emitted by a handler the following must be true:
The logger's effective level must >= message level and it must not
be filtered by a filter attached to the logger, otherwise the
message is discarded.
If the message survives the logger check it is passed to a list of
handlers. A handler will emit the message if the handler's level >=
message level and its not filtered by a filter attached to the
handler.
The list of handlers is determined thusly: Each logger has a list of
handlers (which may be empty). Starting with the logger the message
was bound to the message is passed to each of it's handlers. Then
the process repeats itself by traversing the chain of loggers
through all of it's ancestors until it reaches the root logger. The
logger traversal will be terminated if the propagate flag on a logger
is False (by default propagate is True).
Let's look at a hypothetical logger hierarchy (tree)::
A
/ \
B D
/
C
There are 4 loggers and 3 handlers
Loggers:
+-------+---------+---------+-----------+----------+
|Logger | Level | Filters | Propagate | Handlers |
+=======+=========+=========+===========+==========+
| A | WARNING | [] | False | [h1,h2] |
+-------+---------+---------+-----------+----------+
| A.B | ERROR | [] | False | [h3] |
+-------+---------+---------+-----------+----------+
| A.B.C | DEBUG | [] | True | |
+-------+---------+---------+-----------+----------+
| A.D | | [] | True | |
+-------+---------+---------+-----------+----------+
Handlers:
+---------+---------+---------+
| Handler | Level | Filters |
+=========+=========+=========+
| h1 | ERROR | [] |
+---------+---------+---------+
| h2 | WARNING | [] |
+---------+---------+---------+
| h3 | DEBUG | [] |
+---------+---------+---------+
Each of the loggers and handlers have empty filter lists in this
example thus the filter checks will always pass.
If a debug message is posted logger A.B.C the following would
happen. The effective level is determined. Since it does not have a
level set it's parent (A.B) is examined which has ERROR set,
therefore the effective level of A.B.C is ERROR. Processing
immediately stops because the logger's level of ERROR does not
permit debug messages.
If an error message is posted on logger A.B.C it passes the logger
level check and filter check therefore the message is passed along
to the handlers. The list of handlers on A.B.C is empty so no
handlers are called at this position in the logging hierarchy. Logger
A.B.C's propagate flag is True so parent logger A.B handlers are
invoked. Handler h3's level is DEBUG, it passes both the level and
filter check thus h3 emits the message. Processing now stops because
logger A.B's propagate flag is False.
Now let's see what would happen if a warning message was posted on
logger A.D. It's effective level is WARNING because logger A.D does
not have a level set, it's only ancestor is logger A, the root
logger which has a level of WARNING, thus logger's A.D effective
level is WARNING. Logger A.D has no handlers, it's propagate flag is
True so the message is passed to it's parent logger A, the root
logger. Logger A has two handlers h1 and h2. The level of h1 is
ERROR so the warning message is discarded by h1, nothing is emitted
by h1. Next handler h2 is invoked, it's level is WARNING so it
passes both the level check and the filter check, thus h2 emits the
warning message.
How to configure independent logging spaces:
--------------------------------------------
A common idiom is to hang all handlers off the root logger and set
the root loggers level to the desired verbosity. But this simplistic
approach runs afoul of several problems, in particular who controls
logging (accomplished by configuring the root logger). The usual
advice is to check and see if the root logger has any handlers set,
if so someone before you has configured logging and you should
inherit their configuration, all you do is add your own loggers
without any explicitly set level. If the root logger doesn't have
handlers set then you go ahead and configure the root logger to your
preference. The idea here is if your code is being loaded by another
application you want to defer to that applications logging
configuration but if your code is running stand-alone you need to
set up logging yourself.
But sometimes your code really wants it's own logging configuration
managed only by yourself completely independent of any logging
configuration by someone who may have loaded your code. Even if you
code is not designed to be loaded as a package or module you may be
faced with this problem. A trivial example of this is running your
code under a unit test framework which itself uses the logging
facility (remember there is only ever one root logger in any Python
process).
Fortunately there is a simple way to accommodate this. All you need
to do is create a "fake" root in the logging hierarchy which belongs
to you. You set your fake root's propagate flag to False, set a
level on it and you'll hang your handlers off this fake root. Then
when you create your loggers each should be a descendant of this
fake root. Now you've completely isolated yourself in the logging
hierarchy and won't be influenced by any other logging
configuration. As an example let's say your your code is called
'foo' and so you name your fake root logger 'foo'.::
my_root = logging.getLogger('foo') # child of the root logger
my_root.propagate = False
my_root.setLevel(logging.DEBUG)
my_root.addHandler(my_handler)
Then every logger you create should have 'foo.' prepended to it's
name. If you're logging my module your module's logger would be
created like this::
module_logger = logging.getLogger('foo.%s' % __module__)
If you're logging by class then your class logger would be::
class_logger = logging.getLogger('foo.%s.%s' % (self.__module__, self.__class__.__name__))
How to set levels:
------------------
An instinctive or simplistic assumption is to set the root logger to a
high logging level, for example ERROR. After all you don't want to be
spamming users with debug and info messages. Let's also assume you've
got two handlers, one for a file and one for the console, both
attached to the root logger (a common configuration) and you haven't
set the level on either handler (in which case the handler will emit
all levels).
But now let's say you want to turn on debugging, but just to the file,
the console should continue to only emit error messages.
You set the root logger's level to DEBUG. The first thing you notice is
that you're getting debug message both in the file and on the console
because the console's handler does not have a level set. Not what you
want.
So you go back restore the root loggers level back to it's original
ERROR level and set the file handler's level to DEBUG and the console
handler's level to ERROR. Now you don't get any debug messages because
the root logger is blocking all messages below the level of ERROR and
doesn't invoke any handlers. The file handler attached to the root
logger even though it's level is set to DEBUG never gets a chance to
process the message.
*IMPORTANT:* You have to set the logger's level to the minimum of all
the attached handler's levels, otherwise the logger may block the
message from ever reaching any handler.
In this example the root logger's level must be set to DEBUG, the file
handler's level to DEBUG, and the console handler's level set to
ERROR.
Now let's take a more real world example which is a bit more
complicated. It's typical to assign loggers to every major class. In
fact this is the design strategy of Java logging from which the Python
logging is modeled. In a large complex application or library that
means dozens or possibly hundreds of loggers. Now lets say you need to
trace what is happening with one class. If you use the simplistic
configuration outlined above you'll set the log level of the root
logger and one of the handlers to debug. Now you're flooded with debug
message from every logger in the system when all you wanted was the
debug messages from just one class.
How can you get fine grained control over which loggers emit debug
messages? Here are some possibilities:
(1) Set a filter.
.................
When a message is propagated to a logger in the hierarchy first the
loggers level is checked. If logger level passes then the logger
iterates over every handler attached to the logger first checking the
handler level. If the handler level check passes then the filters
attached to the handler are run.
Filters are passed the record (i.e. the message), it does not have
access to either the logger or handler it's executing within. You
can't just set the filter to only pass the records of the classes you
want to debug because that would block other important info, warning,
error and critical messages from other classes. The filter would have
to know about the "global" log level which is in effect and also pass
any messages at that level or higher. It's unfortunate the filter
cannot know the level of the logger or handler it's executing inside
of.
Also logger filters only are applied to the logger they are attached
to, i.e. the logger the message was generated on. They do not get
applied to any ancestor loggers. That means you can't just set a
filter on the root logger. You have to either set the filters on the
handlers or on every logger created.
The filter first checks the level of the message record. If it's
greater than debug it passes it. For debug messages it checks the set
of loggers which have debug messages enabled, if the message record
was generated on one of those loggers it passes the record, otherwise
it blocks it.
The only question is whether you attach the filter to every logger or
to a handful of handlers. The advantage of attaching the filter to
every logger is efficiency, the time spent handling the message can be
short circuited much sooner if the message is filtered earlier in the
process. The advantage of attaching the filter to a handler is
simplicity, you only have to do that when a handler is created, not
every place in the code where a logger is created.
(2) Conditionally set the level of each logger.
...............................................
When loggers are created a check is performed to see if the logger is
in the set of loggers for which debug information is desired, if so
it's level is set to DEBUG, otherwise it's set to the global
level. One has to recall there really isn't a single global level if
you want some handlers to emit info and above, some handlers error and
above, etc. In this case if the logger is not in the set of logger's
emitting debug the logger level should be set to the next increment
above debug level.
A good question to ask would be why not just leave the logger's level
unset if it's not in the set of loggers to be debugged? After all it
will just inherit the root level right? There are two problems with
that. 1) It wold actually inherit the level any ancestor logger and if
an ancestor was set to debug you've effectively turned on debugging
for all children of that ancestor logger. There are times you might
want that behavior, where all your children inherit your level, but
there are many cases where that's not the behavior you want. 2) A more
pernicious problem exists. The logger your handlers are attached to
MUST be set to debug level, otherwise your debug messages will never
reach the handlers for output. Thus if you leave a loggers level unset
and let it inherit it's effective level from an ancestor it might very
well inherit the debug level from the root logger. That means you've
completely negated your attempt to selectively set debug logging on
specific loggers. Bottom line, you really have to set the level on
every logger created if you want fine grained control.
Approach 2 has some distinct performance advantages. First of all
filters are not used, this avoids a whole processing step and extra
filter function calls on every message. Secondly a logger level check
is a simple integer compare which is very efficient. Thirdly the
processing of a message can be short circuited very early in the
processing pipeline, no ancestor loggers will be invoked and no
handlers will be invoked.
The downside is some added complexity at logger creation time. But
this is easily mitigated by using a utility function or method to
create the logger instead of just calling logger.getLogger().
Like every thing else in computer science which approach you take boils
down to a series of trade offs, most around how your code is
organized. You might find it easier to set a filter on just one or two
handlers. It might be easier to modify the configuration during
execution if the logic is centralized in just a filter function, but
don't let that sway you too much because it's trivial to iterate over
every logger and dynamically reset it's log level.
Now at least you've got a basic understanding of how this stuff hangs
together and what your options are. That's not insignificant, when I
was first introduced to logging in Java and Python I found it
bewildering difficult to get it do what I wanted.
John Dennis
iÿÿÿÿNs %(levelname)s %(message)st notsett debugt infot warnt warningt errort criticalt exceptionc C sj t ƒ } xD | D]<