搜了一下自己的 Blog 一直缺乏一篇 Python logging 模塊的深度使用的文章。其實這個模塊非常常用，也有非常多的濫用。所以看看源碼來詳細記錄一篇屬於 logging 模塊的文章。
整個 logging 模塊的主要部分 1700 來行代碼，還是很簡單的。我們從實際行為來帶大家過下代碼
當我們在寫 logging.info 的時候我們在干啥？
def info(msg, *args, **kwargs): if len(root.handlers) == 0: basicConfig() root.info(msg, *args, **kwargs)
可以看到默認使用的 root.info 接口。
如果我們直接調用的話會默認調用 basicConfig 的初始配置：
_acquireLock() try: 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) finally: _releaseLock()
第一行就是拿一把鎖，我們可以容易判斷， logging 模塊應該是考慮了線程安全的情況。
這里我們沒有 filename 所以直接會初始化一個流 handler StreamHandler 在這里會傳入一個 None 最后會得到一個標准輸出 sys.stderr。
之后就是得到一些默認配置，然后設置一下輸出的格式化方法最后 set 上 handler。
最后為 root 添加上這個流處理的 handler。
完成后釋放鎖。
這樣我們就完成了 baseConfig 的初始化。 當然你在平時看到的其他 blog 中肯定有介紹初始化 config 的各種方法，其實他們在做的就是覆蓋上面那些代碼的一些參數。修改成自定義的參數。
那么可能大家會問了， root.info 這個 root 是什么定義呢？
我們來看代碼：
root = RootLogger(WARNING) Logger.root = root Logger.manager = Manager(Logger.root)
由於上面代碼是會在 logging 被 import 的時候就執行，所以 root 會直接被賦值。讓我們來看看 RootLogger 初始化的時候發生了什么。
class RootLogger(Logger): def __init__(self, level): """ Initialize the logger with the name "root". """ Logger.__init__(self, "root", level)
沒什么看點 讓我們來看父類 logger.__init__ 實現了什么
class Logger(Filterer): def __init__(self, name, level=NOTSET): Filterer.__init__(self) self.name = name self.level = _checkLevel(level) self.parent = None self.propagate = 1 self.handlers = [] self.disabled = 0
這里默認 name 是 root。 然后會初始化這些參數最后返回這個 logger 對象。
logger 有非常多的方法其中就包括 .info .error .warn 之類的直接打印日志的方法。
def info(self, msg, *args, **kwargs): """ Log 'msg % args' with severity 'INFO'. To pass exception information, use the keyword argument exc_info with a true value, e.g. logger.info("Houston, we have a %s", "interesting problem", exc_info=1) """ if self.isEnabledFor(INFO): self._log(INFO, msg, args, **kwargs)
當我們再調用 logging.info 的時候就是在調用 logger('root').info
當我們知道這點時候 就繼續來看一下 logger 是怎么打日志的吧。
調用 self._log 方法其實就是調用 logger._log 方法
def _log(self, level, msg, args, exc_info=None, extra=None): if _srcfile: try: fn, lno, func = self.findCaller() except ValueError: fn, lno, func = "(unknown file)", 0, "(unknown function)" else: fn, lno, func = "(unknown file)", 0, "(unknown function)" if exc_info: if not isinstance(exc_info, tuple): exc_info = sys.exc_info() record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra) self.handle(record)
如果沒有什么特別的參數配置
會直接初始化 record 調用 makeRecord 方法。最后調用自己的 handle 方法。我們可以先來看下 makeRecord 方法。
在看這個代碼之前可以先為大家明確一下 logRecord 在 logging 日志模塊里面意義。就是說我們每打印的一條日志 其實就是一個 logRecord 實例。好我們來看代碼
def __init__(self, name, level, pathname, lineno, msg, args, exc_info, func=None): """ Initialize a logging record with interesting information. """ ct = time.time() self.name = name self.msg = msg # # The following statement allows passing of a dictionary as a sole # argument, so that you can do something like # logging.debug("a %(a)d b %(b)s", {'a':1, 'b':2}) # Suggested by Stefan Behnel. # Note that without the test for args[0], we get a problem because # during formatting, we test to see if the arg is present using # 'if self.args:'. If the event being logged is e.g. 'Value is %d' # and if the passed arg fails 'if self.args:' then no formatting # is done. For example, logger.warn('Value is %d', 0) would log # 'Value is %d' instead of 'Value is 0'. # For the use case of passing a dictionary, this should not be a # problem. # Issue #21172: a request was made to relax the isinstance check # to hasattr(args[0], '__getitem__'). However, the docs on string # formatting still seem to suggest a mapping object is required. # Thus, while not removing the isinstance check, it does now look # for collections.Mapping rather than, as before, dict. if (args and len(args) == 1 and isinstance(args[0], collections.Mapping) and args[0]): args = args[0] self.args = args self.levelname = getLevelName(level) self.levelno = level self.pathname = pathname try: self.filename = os.path.basename(pathname) self.module = os.path.splitext(self.filename)[0] except (TypeError, ValueError, AttributeError): self.filename = pathname self.module = "Unknown module" self.exc_info = exc_info self.exc_text = None # used to cache the traceback text self.lineno = lineno self.funcName = func self.created = ct self.msecs = (ct - long(ct)) * 1000 self.relativeCreated = (self.created - _startTime) * 1000 if logThreads and thread: self.thread = thread.get_ident() self.threadName = threading.current_thread().name else: self.thread = None self.threadName = None if not logMultiprocessing: self.processName = None else: self.processName = 'MainProcess' mp = sys.modules.get('multiprocessing') if mp is not None: # Errors may occur if multiprocessing has not finished loading # yet - e.g. if a custom import hook causes third-party code # to run when multiprocessing calls import. See issue 8200 # for an example try: self.processName = mp.current_process().name except StandardError: pass if logProcesses and hasattr(os, 'getpid'): self.process = os.getpid() else: self.process = None
可以看到各種參數，包括打印所需要的當前時間戳，名字要打印的內容。包括一些帶進來的參數，需要打印時候的 level 等級。都會被賦到這個 logRecord 實例上面。
拿到這個 record 之后就是執行 logger.handle 方法了。並且傳入 record 實例對象。
def handle(self, record): """ Call the handlers for the specified record. This method is used for unpickled records received from a socket, as well as those created locally. Logger-level filtering is applied. """ if (not self.disabled) and self.filter(record): self.callHandlers(record)
如果說沒有被 self.filter 過濾的話。注意這里的 handle 方法是是 logger 的。filter 方法卻是基類 filter 的。 filter 這里會去取之前 add 進 handler 的 filter 方法是一個數組， Logger 和 Handler 類的 父類都是 Filterer類 他會維護一個 self.filters 的數組。
然后我們調用 callHandlers 方法
def callHandlers(self, record): """ Pass a record to all relevant handlers. Loop through all handlers for this logger and its parents in the logger hierarchy. If no handler was found, output a one-off error message to sys.stderr. Stop searching up the hierarchy whenever a logger with the "propagate" attribute set to zero is found - that will be the last logger whose handlers are called. """ c = self found = 0 while c: for hdlr in c.handlers: found = found + 1 if record.levelno >= hdlr.level: hdlr.handle(record) if not c.propagate: c = None #break out else: c = c.parent if (found == 0) and raiseExceptions and not self.manager.emittedNoHandlerWarning: sys.stderr.write("No handlers could be found for logger" " \"%s\"\n" % self.name) self.manager.emittedNoHandlerWarning = 1
通過 logger 上掛的 handler 數組，依次拿出來調用 handle 方法處理 record 對象。
def handle(self, record): """ Conditionally emit the specified logging record. Emission depends on filters which may have been added to the handler. Wrap the actual emission of the record with acquisition/release of the I/O thread lock. Returns whether the filter passed the record for emission. """ rv = self.filter(record) if rv: self.acquire() try: self.emit(record) finally: self.release() return rv
這個方法是 Handler 類的方法。還記得嗎 剛才我們初始化的是 StreamHandler 方法, Handler 類是它的父類。
然后這里會再次調用 handler 的 自身的 filter 方法。如果過濾之后依然有結果就加鎖 調起 emit 方法開始打日志。
這里會使用 StreamHandler 方法的 emit 方法。
def emit(self, record): """ Emit a record. If a formatter is specified, it is used to format the record. The record is then written to the stream with a trailing newline. If exception information is present, it is formatted using traceback.print_exception and appended to the stream. If the stream has an 'encoding' attribute, it is used to determine how to do the output to the stream. """ try: msg = self.format(record) stream = self.stream fs = "%s\n" if not _unicode: #if no unicode support... stream.write(fs % msg) else: try: if (isinstance(msg, unicode) and getattr(stream, 'encoding', None)): ufs = u'%s\n' try: stream.write(ufs % msg) except UnicodeEncodeError: #Printing to terminals sometimes fails. For example, #with an encoding of 'cp1251', the above write will #work if written to a stream opened or wrapped by #the codecs module, but fail when writing to a #terminal even when the codepage is set to cp1251. #An extra encoding step seems to be needed. stream.write((ufs % msg).encode(stream.encoding)) else: stream.write(fs % msg) except UnicodeError: stream.write(fs % msg.encode("UTF-8")) self.flush() except (KeyboardInterrupt, SystemExit): raise except: self.handleError(record)
然后就愉快的寫到 流里面去了，就結束了整個流程。
其實只要理解了這個流程，會發現打日志還是很簡單的。我們平常的使用無法就是在這個流程上修改一些配置，或者初始化的時候不使用 root 而使用自定義的 名字然后增加一些自定義的配置 XD.
Reference:
https://juejin.im/post/5b13fdd0f265da6e0b6ff3dd Pycon2018 利用logging模塊輕松地進行Python日志記錄