Introduction to Autologging¶

Release:	1.3.0

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 than logging.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 set phrase 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

@traced
@logged
class MyClass:

   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.

Introduction to Autologging¶

Logging and tracing “by hand”¶

Logging and tracing with autologging¶

Logging and tracing with `autologging`¶