Per-file/module logger in Python

Question

I have some Python code I need to add logging to.

I've always preferred nice big C macro looking statements like "DEBUG()", "ERROR()", etc for logging. I feel it makes the code easier to read (no objects) when trace-points are visually differentiable from the actual code.

I also would like to be able to set logging levels at a per-module level.

How could I make a module called "log" that is capable of doing this (while making use of the Python std library logging module)?

E.g.:

File: main.py

# This imports LOG_MODULE_NAME, DEBUG, WARN, etc
from log import *
import my_module

LOG_MODULE_NAME("main")

log.set_level("main", log.LVL_DEBUG)
log.set_level("my_module", log.LVL_WARN)

if __name__ == "__main__":
    foo = my_module.myFunc(2)

DEBUG("Exiting main.py")

File: my_module.py

from log import *

LOG_MODULE_NAME("my_module")


def myFunc(x):
    DEBUG("Entering function")
    if x != 1:
         WARN("I thought it would be 1")
    DEBUG("Exiting function")
    return x+1

I'd expect output to look something like:

[WARN:my_module - my_module.py:9] I thought it would be 1
[DEBUG:main - main.py:11] Exiting main.py

Answer 1

These answers seem to skip the very simple idea that functions are first-class objects which allows for:

def a_function(n):
    pass

MY_HAPPY_NAME = a_function
MY_HAPPY_NAME(15) # which is equivalent to a_function(15)

Except I recommend that you don't do this. PEP8 coding conventions are widely used because life is too short to make me have to read identifiers in the COBOLy way that you like to write them.

Some other answers also use the global statement which is almost always not needed in Python. If you are making module-level logger instances then

import logging

log = logging.getLogger(__name__)

def some_method():
    ...
    log.debug(...)

is a perfectly workable, concise way of using the module-level variable log. You could even do

log = logging.getLogger(__name__)
DEBUG = log.debug

def some_method():
    ...
    DEBUG(...)

but I'd reserve the right to call that ugly.

Answer 2

To expand on the @2rs2ts notion, you can just log by module too as shown in the Python logging HOWTO.

A good convention to use when naming loggers is to use a module-level logger, in each module which uses logging, named as follows:

logger = logging.getLogger(__name__) 

This means that logger names track the package/module hierarchy, and it’s intuitively obvious where events are logged just from the logger name

Make the first 2 lines of all your files this:

import logging
logger = logging.getLogger(__name__) 

Then you have per-module logging that is easily customizable.

You can log to different levels via:

logger.debug("I just saw this %s" , var )
logger.info("I just saw this %s" , var )
logger.warn("I just saw this %s" , var )

Note that I passed the string templating variable as an *arg, and not a % to immediately template the string. If your logger is set to be higher than the level you log at, you save yourself the CPU cycles. There are a handful of tricks like that in the logging docs.

You can set the logging level and where to log on whatever app/script you run; the logging module will handle the rest.

Answer 3

If you want to have the logger's name indicate the module in which it was used, you can use the logger.getLogger([name]) module function, and pass __name__ as its (optional) argument, as explained here.

If you want to use names like DEBUG(), do something like this in each of your files...

LOG_MODULE_NAME = logging.getLogger(__name__)

def DEBUG(msg):
    global LOG_MODULE_NAME
    LOG_MODULE_NAME.debug(msg)

I am not clear on the way that global namespaces actually work in Python... this answer says

each module has its own "global" namespace.

So I guess you will be just fine like that, since LOG_MODULE_NAME won't collide between modules.

I believe that this approach will give you one logfile, where the lines will look like this:

DEBUG:my_module:Entering function
WARN:my_module:I thought it would be 1
DEBUG:my_module:Exiting function
DEBUG:root:Exiting main.py

Not instrospective enough? You want the inpsect module, which will give you a lot of information about the program while it's running. This will, for instance, get you the current line number.

Your note about "setting log levels at a per-module level" makes me think that you want something like getEffectiveLevel(). You could try to smush that in like this:

LOG_MODULE_NAME = logging.getLogger(__name__)
MODULE_LOG_LEVEL = log.LVL_WARN

def DEBUG(msg):
    if MODULE_LOG_LEVEL = log.LVL_DEBUG:
        global LOG_MODULE_NAME
        LOG_MODULE_NAME.debug(msg)

I'm not experienced enough with the logging module to be able to tell you how you might be able to make each module's log change levels dynamically, though.

Answer 4

The cleaner solution can be found on this other question. The cleaner way to configure logging for a library is to use these few lines in each of your module.

import logging
logging.getLogger(__name__).addHandler(logging.NullHandler())

You main script (e.g. my script.py) is responsible for:

• doing the logging configuration, e.g. with logging.basicConfig() or logging.config.dictConfig()
• choosing the Formatter to use for your log events.
• choosing the logging.handlers to use to dispatch the events to the correct place (e.g. remote logging, console, file ...)

---

Take your example:

def myFunc(x):
    DEBUG("Entering function")
    if x != 1:
         WARN("I thought it would be 1")
    DEBUG("Exiting function")
    return x+1

and your expected output:

[WARN:my_module - my_module.py:9] I thought it would be 1
[DEBUG:main - main.py:11] Exiting main.py

How do we figure out that the DEBUG("Existing main.py") happened on main.py:11 ? The obvious answer is you cannot unless you inspect the frame and check who the caller is. If you want to define DEBUG() function in a log.py module, then you won't get the correct records. Functions are very different from macros, you have to define a function and there is no inline replacement, so you are effectively not in the same frame anymore.

Just for kicks, I wrote a solution using introspection with the inspect module (note: don't run this as production code), but the reality is that in order to answer the challenges "where was this function called and at what line?" some work needs to be done.

• bar.py

  # file: bar.py
  # this is just a module to show DEBUG works when used in a different module
  from log import DEBUG
  
  def baz():
      DEBUG('oh hai from baz')
  

• log.py

  # file: log.py
  import inspect
  import logging
  
  def DEBUG(msg, *args):
      curframe = inspect.currentframe()
      try:
          # http://docs.python.org/2/library/inspect.html#inspect.getouterframes
          _, filename, _, code, _, _ = inspect.getouterframes(curframe, 2)[1]
          logging.debug('[%s:%s] '+msg, filename, code, *args)
      finally:
          del curframe
  

• main script script.py

  # file: script.py
  # responsible for the logging setup.
  import logging
  from log import DEBUG
  from bar import baz
  
  def foo():
      DEBUG('oh hai')
  
  if __name__ == '__main__':
      logging.basicConfig()
      logging.root.setLevel(logging.DEBUG)
      foo()
      baz()
  

The obvious problem with my solution is that the we only use the root logger:

$ python script.py 
DEBUG:root:[script.py:foo] oh hai
DEBUG:root:[/Users/dnozay/Desktop/bar.py:baz] oh hai from baz

Given all these elements, I would discourage re-implementing the functionality already available in logging.