Recently I came across a python codebase like below:
Main.py
import A as a
import B as b
logger = logging.getLogger(__name__)
a.logger = logger
b.logger = logger
A.py
logger = None # set from main
B.py
logger = None # set from main
What is the problem with that? What is good practice to use logger? To answer these questions, let's look at how python logger works. Python logging module is influenced by log4j java logging framework. So we will see many things can be applied to java logging as well.
Logging module class diagram
Each logger instance can have multiple handlers, each handler can have one formatter which contains the log message format. Each logger has a parent pointer to its parent. Below is the python logger module's internal class diagram.
-
The loggers are arranged as hierarchy tree based on the name's dotty namespace hierarchies. The top is root logger. For example, logger named 'a.b.c''s parent is a logger named 'a.b' whose parent is logger named 'a' whose parent is the root logger.
Logging configuration
The root logger can be configured by basicConfig() method and can only be configured once. It does basic configuration for the logging system. The function does nothing if the root logger already has handler configured. It is a convenience method intended for use by simple script to do one-shot configuration of the logging package.
FORMAT = "[%(filename)s:%(lineno)s - %(funcName)10s() ] %(message)s"
logging.basicConfig(format=FORMAT)
ANOTHER_FORMAT = "[%(filename)s:%(lineno)s] %(message)s"
logging.basicConfig(format=ANOTHER_FORMAT)
The above second call won't have any effect.
Logger creation
Logger is obtained by a factory method.
logger = logging.getLogger(__name__)
The above method will register logger in an internal logger instance cache keyed by the module name. It returns a logger with the specified name, creating it if necessary. If no name is specified, return the root logger.
Thread safety
Both method getLogger and basicConfig are thread safe by acquiring a lock. Below is the source code from python 2.7
#_lock is used to serialize access to shared data structures in this module.
#This needs to be an RLock because fileConfig() creates and configures
#Handlers, and so might arbitrary user threads. Since Handler code updates the
#shared dictionary _handlers, it needs to acquire the lock. But if configuring,
#the lock would already have been acquired - so we need an RLock.
#The same argument applies to Loggers and Manager.loggerDict.
#
if thread:
_lock = threading.RLock()
else:
_lock = None
def
_acquireLock():
"""
Acquire the module-level lock for serializing access to shared data.
This should be released with _releaseLock().
"""
if _lock:
_lock.acquire()
def
_releaseLock():
"""
Release the module-level lock acquired by calling _acquireLock().
"""
if _lock:
_lock.release()
Log message propagation
The most important, log messages are bubbled up, just like event bubbling in browser, from children all the way to root.
Asynchronized logging
One of most import aspects of logging inside web application is the logging should be asynchronized, since I/O operation is blocking. The standard python logging module doesn't have async handler.
Initialize logger
We can initialize logger at the module level like the above example or at the class instance level.
A.py
import logging
logger = None
class A(object):
def __init__(self, params):
logger = logging.getLogger(__name__)
The benefit of setting logger at the class level is that the logger is lazy initialized only when the class A is created and used.
So the problem with the approach mentioned at the beginning is that all python modules use the same logger, there is no hierarchy. We lose the benefit of attaching different log handler to the loggers and message propagation.
Conclusion
As conclusion let's look at the following example,
Main.py
import logging
import A
rootLogger = logging.getLogger()
rootLogger.setLevel(logging.DEBUG)
rootLogger.addHandler(logging.FileHandler("main.log"))
A.py
logger = logging.getLogger(__name__)
logger.setLevellogging.DEBUG)
logger.addHandlerlogging.FileHandler("app.log"))
logger.info('logging message at A')
What will be the end result? The message will appear in both logs!
