Introduction to Autologging¶
Release: | 1.0.1 |
---|
When using the Python logging
module to log classes, there are a
couple of challenges that usually must be addressed by the developer:
- The standard
logging
module is not inherently “aware” of classes in the context of logging statements made within class methods. - The standard
logging
module has no concept of tracing (i.e. there are neither log methods for tracing nor any log levels lower thanlogging.DEBUG
to use for tracing). (See logging vs. tracing.)
Challenge #1 is not a failing of the logging
module, but rather a
side-effect of using Python stack frames to determine caller information
(see logging.Logger.findCaller
).
A reasonable workaround for #1 is to simply create a class-level logger
that uses the class’s qualified name as the
logger name. This approach is consistent with respect to the logging
module’s recommended usage for
logger naming (as well as being analogous to java.util.logging
and log4j usage, upon which
Python’s logging
module is based).
Challenge #2 can also be worked around, though it requires a bit more
effort. Defining a new log level/name for tracing (via
logging.addLevelName
) is a start, but writing (and maintaining)
the tracing log statements becomes tedious and error prone. In a
language as dynamic as Python, it should not be (and isn’t) necessary
to do this “by hand.”
As it turns out, the code necessary to create appropriately-named
loggers for classes and to trace functions or class methods is
boilerplate. The autologging
module encapsulates this boilerplate
code for you, allowing you to use simple decorators to get consistent
class logging and tracing.
Logging and tracing “by hand”¶
# my_module.py
import logging
logging.addLevelName(1, "TRACE")
class MyClass:
__log = logging.getLogger("{}.MyClass".format(__name__))
def my_method(self, arg, keyword=None):
self.__log.log(TRACE, "CALL %r keyword=%r", arg, keyword)
self.__log.info("my message")
phrase = "%s and %s" % (arg, keyword)
self.__log.log(TRACE, "RETURN %r", phrase)
return phrase
Assuming we’ve already configured logging to use the format “%(levelname)s:%(name)s:%(funcName)s:%(message)s”, calling “my_method” produces the following log output:
TRACE:my_module.MyClass:my_method:CALL 'spam' keyword='eggs'
INFO:my_module.MyClass:my_method:my message
TRACE:my_module.MyClass:my_method:RETURN 'spam and eggs'
Using this approach, we end up with several lines of visual clutter:
- The purpose of “my_method” is to join the arg and keyword together into a phrase, but there are more lines dedicated to logging/tracing than to the method logic.
- Because we wish to trace the return value of the method, we must
set the return value as an intermediate local variable so that it can
be traced, then returned.
This means we can’t simply use the much more succinct expression
return "%s and %s" % (arg, keyword)
.
Aside from visual clutter, there are maintenance issues as well:
- If the name of the class changes, the logger name should be updated accordingly.
- If anything about the method signature changes (number and/or position of arguments, number and/or names of keyword arguments), then the “CALL” tracing log statement must be updated manually.
- If “my_method” were ever refactored to, say, return with a different
value if keyword is
None
, then we’d need to either add another logging statement to trace the early return, or we’d need to reconstruct the method body to setphrase
accordingly before tracing and returning.
Logging and tracing with autologging
¶
Autologging addresses all of the issues in the previous sample, resulting in less code that’s more readable and easier to maintain:
# my_module.py
from autologging import logged, traced
@logged
@traced
class MyClass:
def def my_method(self, arg, keyword=None):
self.__log.info("my message")
return "%s and %s" % (arg, keyword)
The method is now much easier to follow visually, requires zero logging or tracing “maintenance,” and produces log output that is semantically identical to the previous example:
TRACE:my_module.MyClass:my_method:CALL *('spam',) **{'keyword': 'eggs'}
INFO:my_module.MyClass:my_method:my message
TRACE:my_module.MyClass:my_method:RETURN 'spam and eggs'
Please see The autologging API for details, then check out Examples of using autologging.