Python logging modules can be confusing places

Python logging module is mainly Python provided by the general log system, the use of the method is actually very simple, this piece is not much introduction. The following is mainly about the use of the Python logging module, involving multiple Python file calls, and each file set the corresponding logging way different, may produce confusing phenomenon.

The following is the background of the narrative that I encountered when I was developing:

There are three Python modules A, B, C. The main module A will import B and C modules, the main module has a corresponding logging mode,

A the way to use the logging module is:

Import Logging
Import Logging.handlers
defCreatelogger (LogFile ='Batch'): Handler= Logging.handlers.RotatingFileHandler (str (logFile) +'. LOG', MaxBytes = 1024x768 * 1024x768, Backupcount = 5) FMT='% (asctime) s-% (filename) s:% (lineno) s-% (name) s-% (message) s'Formatter=logging. Formatter (FMT) handler.setformatter (Formatter) Logger=Logging.getlogger (str (logFile)) Logger.addhandler (handler) logger.setlevel (Logging.info)returnLogger
Slogger = Createlogger ()

in fact a module using logging is a simple way to create a Rotatingfilehandler, the number of log files and the maximum size of each log file is controlled by Rotatingfilehandler rollback logging. and create a formatter object to format the log file. Using the logging object generated by this method in the program to log, it is obvious that in this way, the log will be printed to the corresponding log file.

b The logging module is used in the form of

def GetLogger (testname): = Logging.getlogger (testname)    logger.setlevel (logging.info)    '.       LOG')    hdlr.setlevel (logging.info)    = logging. Formatter ("[% (asctime) s]\t[% (levelname) s]\t[% (thread) d]\t[% (pathname) s:% (Lineno) d]\t% (message) s")    hdlr.setformatter (formatter)    Logger.addhandler (HDLR)      return  Logger

Logger = GetLogger (' OK ')

def setlogger (log):
Global Logger
Logger = Log

B Module Default logging way is similar to a, just B choose logging Way is to a log file to hit log. A in fact, in the actual use of the corresponding function B module and the class is not directly in the logging mode of B, but to B logging a redirect, which can be function from the function of Setlogger functions. A directly passes an already logging object to B, so B can also share the same logging object with a, and the log will be hit in a set file. This is for a master module to invoke the logic of multiple sub-modules , and each sub-module has a corresponding logging usage, hit different files to unify or good, so as to effectively control the total log file size and quantity.

But did not pay attention to the C module, and then found that a program in the process will be a, B module log information directly to the screen, and the log file also has a corresponding log. These are confusing, the call to the B module is commented out, you will still find a log directly hit the screen. But the code that sets the logging object in the A program is taken out separately, everything is normal.

According to the situation at that time, can only suspect that the C module has what settings, will cause a, B module to play log the way some changes. Later realized that the C module did not set the logging object, but directly using Logging.info to hit log. The logic of this part of the comments off, found that a, B dozen log the way back to normal, will never go to the screen to hit log.

Find some interesting phenomena by seeing the code of the Python logging module:

1. The logging object is actually a tree structure, and each created logging object is the child node of the root logging object. When constructing logging objects using the GetLogger (name=none) function of the logging module, if name is None, this results in a root logging object. If name contains., such as name = ' A.B.C ', in this way will produce 3 logging objects, respectively, C, B, a,c->b->a->root,root tree root node, a root child node, B is a child node, c is a child node, and so on.

2. The root node is global, although multiple modules are involved in the process, but they share a root node.

3. Each logging object hit log, will also pass the log information to the upper logging object, for C->b->a->root this case, this log will actually play 4 times, with C, B, a, root sequentially hit a log.

One might ask, like I used to initialize a logging object in the same way as a module or a B module, so that the initialized object would be a child of the root logging object, and the root logging object would normally hit the log on the screen. Under normal circumstances, the log will be two copies, one will hit the file, one will hit the screen. So why is the fact that only the log file has the corresponding log, but there is no display of objects on the screen?

In fact, if the process is a little curious, the way directly accustomed to some doubts, and with such curiosity to explore, I believe there will be more gains.

So, the more confusing is, why I call a module generated by the slogger.info out of the log, only the log file has, and root logging why not hit log to hit the screen. Why root logging does not work. This time, you can look at the logging __init__.py code, you will find that the root logging info code is as follows:

def info (msg, *args, * *Kwargs)    :"" "    Log a message with severity ' info ' on the root Logger.     """    if len (root.handlers) = = 0:        basicconfig (    )*args, **kwargs)

The above code relates to Root.handlers, which is suspected to be related to the way the root.handlers is played with log. Therefore, print Len (root.handlers) finds the result to be 0. That is, the default root logging corresponding to the handlers is [], so that the result is Slogger log, root logging will not play any log. Add the following code to the __main__:

if __name__ = = ' __main__ ':    slogger.info (' OK ')    print len (logging.root.handlers), Logging.root.handlers    Logging.info (' bad ')    print len (logging.root.handlers), logging.root.handlers

Run the program and get the following results:

0 []
1 [<logging. Streamhandler instance at 0x7f066e3eef80>].

The first line results in 0 [] very good explanation, why the root logging object is normally not typed log.

After calling Logging.info (' bad '), the Root.handlers object is the Streamhandler object. This program allows you to see changes in the root logging object before and after the call to the Logging.info object.

There is also a need to verify that the logging call before and after the normal module logging way.

Write the following code in __MAIN__:

if __name__ = = ' __main__ ':    for I in Xrange (0, 2):        slogger.info (' OK ')        logging.info (' bad ')

according to the previous analysis, the first call to Slogger.info (' OK ') is not to log, and the Logging.info itself is due to the warning level, so there is no log, and the second will play log on the screen. So, as a result, there are three logs in the log file, and there is a INFO:batch:OK on the screen. It's quite consistent with what I had guessed before.

Why does this shift occur after Logging.info is called?

Continue reading the root logging info above and follow the Basicconfig code below. will notice len (root.handlers) = = 0 will go to call basicconfig, this time you can notice, basicconfig the implementation of this module.

def basicconfig (**kwargs):      If Len (root.handlers) = = 0:        filename = kwargs.get ("filename")        if filename:            mode = Kwargs.get ("FileMode", ' a ')            HDLR = filehandler (filename, mode)        else:            stream = Kwargs.get (" Stream ")            HDLR = Streamhandler (stream)        fs = Kwargs.get (" format ", Basic_format)        DFS = kwargs.get (" Datefmt ", None)        FMT = Formatter (FS, Dfs)        hdlr.setformatter (FMT)        Root.addhandler (HDLR) Level        = Kwargs.get ( ' Level ') if level was not        None:            root.setlevel (Level)

As you can see, when the length of the root.handlers is 0, a default Streamhandler object is created, and the pattern that this object sets causes the case that log will hit the screen. This is quite consistent with the results of the previous logging.root.handlers. It must be clear from these that the way in which I have previously encountered a call to Logging.info in a C file affects the upper module and the submodule it calls.

Through the problems I encountered, as well as the analysis of the relevant parts of logging, I would have a deeper understanding of the logging module. The most critical point, if you want to control the logging as precisely as possible, it is important to note that the main module and the corresponding sub-module specifically do not use the logging to play log directly.

Python logging modules can be confusing places