The python logging module may be confusing.

The python logging module may be confusing.
The python logging module is mainly a general-purpose log system provided by python. The method used is actually quite simple. The following describes how to call multiple python files when using the python logging module. Different logging methods are set for each file, which may lead to confusion. The following background describes the problems encountered during development: There are three python modules A, B, and C. The main module A will import module B and Module C. The main module has the corresponding logging mode. The method of using the logging module A is: import loggingimport logging. handlersdef CreateLogger (logFile = 'batch'): handler = logging. handlers. rotatingFileHandler (str (logFile) + '. log', maxBytes = 1024*1024*500, 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) return loggersLogger = CreateLogger () In fact, the method of using logging in module A is very simple. Create A RotatingFileHandler, rotatingFileHandler is used to roll back logging to control the number of LOG files and the maximum size of each LOG file. Create a Formatter object to set the LOG file format. Logging objects generated in this method are used in the program to create logs. Obviously, logs are printed to the corresponding LOG files. B uses the logging module def GetLogger (testName): logger = logging. getLogger (testName) logger. setLevel (logging. INFO) hdlr = logging. fileHandler (testName + '. log') hdlr. setLevel (logging. INFO) formatter = 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 loggerlogger = GetLogger ('OK') def SetL Ogger (log): global logger = the default logging mode of log B is similar to that of log a, but B selects the logging mode to LOG to A log file. In fact, when actually using the functions and classes corresponding to Module B, A does not directly use the logging method of Module B, but instead redirects B logging, this function can be used by the SetLogger function. A will directly pass the logging object to B, so that B can share the same logging object with A and send the LOG to the file set by. This is advantageous for a main module to call the logic of multiple sub-modules, and each sub-module has a corresponding logging usage method, and it can be unified into different files, this effectively controls the total size and quantity of LOG files. But I didn't pay attention to Module C. Then I found that during the running process of program A, the LOG information of module A and Module B is directly sent to the screen, in addition, the LOG file also has the corresponding LOG. These are confusing. If you comment out the call to Module B, you will still find that the LOG of module A directly hits the screen. However, the code for setting the logging object in program A is taken out separately, and everything works normally. According to the current situation, we can only doubt the setting in Module C, which may lead to some changes in the LOG logging method of module A and Module B. Later, I realized that the C Module did not set the logging object, but directly used logging.info to LOG. Comment out the logic of this Part, and find that the method of logging A and B is back to normal, and no longer logs to the screen. By referring to the python logging module code, we can find some interesting phenomena: 1. the logging object is actually a tree structure, and each created logging object is the child node of the root logging object. When you use the getLogger (name = None) function of the logging module to construct a logging object, if the name is None, a root logging object is generated. If the name contains ., for example, name = 'a. b. c '. In this way, three logging objects are generated, namely c, B, a, c-> B-> a-> root, and the root node of the root tree, a is the root child node, B is the child node, c is the child node, and so on. 2. The root node is global. Although multiple modules are involved in this process, they share a root node. 3. when a logging object logs, it also transmits the LOG information to the upper-layer logging object. for c-> B-> a-> root, in fact, this LOG will be typed four times, and a LOG will be typed in order of c, B, a, and root. Someone may ask, as I used to initialize A logging object in the way of module A or Module B, so that the initialized object will also be A child of the root logging object, while the root logging Object usually hits the screen, it is reasonable to say that under normal circumstances, the LOG will be played in two copies, one will hit the file, and the other will hit the screen. So why is there only a corresponding LOG in the LOG file, but there is no object displayed on the screen? In fact, if you are curious about this process and have some doubts about the method that you just take for granted, and are curious about it, I believe there will be more gains. Therefore, it is confusing why the LOG generated by the sLogger.info Module I call is only contained in the LOG file, while the root logging does not hit the screen. Why does root logging not work. In this case, you can check logging _ init __. py code, you will find that the code of root logging info is as follows: def info (msg, * args, ** kwargs ): "Log a message with severity 'info' on the root logger. "if len (root. handlers) = 0: basicConfig () root.info (msg, * args, ** kwargs) the above Code involves root. handlers, suspected root. handlers is related to the logging method. Therefore, print len (root. handlers) and the result is 0. That is to say, the handlers corresponding to the default root logging is []. As a result, when sLogger logs, root logging does not play any logs. Add the following code to _ 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 runs the program and the following running result is obtained: 0 [] 1 [<logging. streamHandler instance at 0x7f066e3eef80>]. The result of the first line is 0 [], which explains why the root logging object does not output logs normally. After calling logging.info ('bad'), the root. handlers object is the StreamHandler object. Through this program, we can see the changes of the root logging object before and after calling the logging.info object. Another point that needs to be verified is the way logging is used to call the normal module before and after logging. In _ main _, write the following code: if _ name _ = '_ main _': for I in xrange (0, 2 ): sLogger.info ('OK') logging.info ('bad') according to the previous analysis, the first call of sLogger.info ('OK') will not hit the LOG, and logging.info itself is not at the WARNING level, therefore, LOG is not recorded, and the second LOG is recorded on the screen. Therefore, the result is that there are three logs in the LOG file, and there is an INFO: batch: OK on the screen. It is quite consistent with the previous conjecture. Why does this change occur after logging.info is called? Continue to read the above root logging info and compare it with the following basicConfig code. You will notice that len (root. handlers) = 0 will call basicConfig. At this time, you can pay attention to the implementation of the basicConfig 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 is not None: root. setLevel (level) can be seen when the root. when the length of handlers is 0, a default StreamHandler object is created, and the mode set for this object causes the LOG to hit the screen. This is quite consistent with the previous results of logging. root. handlers. Through these, I must understand why the method of calling logging.info in the C file that I encountered previously affects the upper-layer module and Its submodules. Through the problems I encountered and the analysis of the related parts of logging, I must have a deeper understanding of the logging module. The most critical point is that to control the logging mode as accurately as possible, you must note that the main module and its corresponding submodules do not directly use logging to LOG.