python logging詳解及自動添加上下文信息

 

　　之前寫過一篇文章日志的藝術（The art of logging），提到了輸出日志的時候記錄上下文信息的重要性，我認為上下文信息包括：

• when：log事件發生的時間
• where：log事件發生在哪個模塊（文件、函數）
• how important：log 事件的緊急程度
• who：事件產生者的唯一標識
• what：具體的事件內容，以及其他所必須的上下文信息

　　其中，when、where、how important都很容易通過logging框架自動包含，但是who（事件生產者的唯一標識）就不能框架自動填充了。比如在服務器端，同時有大量的用戶，如果日志缺乏用戶唯一標識，如（User can not login），那么可以說這樣的日志是毫無意義的。特別是當線上出問題的時候，而且是偶發的問題的時候，日志往往是查找問題的唯一途徑，如果這個時候日志信息不充分，那就很讓人抓狂了。

　　雖然在團隊中強調過很多次，但是很多同事還是會輸出毫無意義的log，也曾試過靜態代碼檢查或者運行時分析，不過都不太優雅，於是希望能夠自動添加一些重要的上下文信息，比如用戶唯一標識。

　　雖然每天都在打log，但事實上我以前也沒有深度了解過python logging模塊，於是借着這個機會，仔細看了一下logging文檔與源碼。

　　這里補充一句，雖然網上有很多文章介紹python logging模塊，但還是建議直接看官方資料，順序如下：tutorial、api document、cookbook、源碼

　　本文地址：https://www.cnblogs.com/xybaby/p/9197032.html

初識python logging

　　logging模塊是python官方提供的、標准的日志模塊。看代碼的話是借鑒了許多log4j中的概念和思想。

　　logging模塊包括以下幾大組件：

• Loggers expose the interface that application code directly uses.
• Handlers send the log records (created by loggers) to the appropriate destination.
• Filters provide a finer grained facility for determining which log records to output.
• Formatters specify the layout of log records in the final output.

　　下面結合一個更完整的例子來逐個介紹。example1.py

import logging
class ContextFilter(logging.Filter):
    def filter(self, record):
        record.userid = '123'
        return True


if __name__ == '__main__':
    # create logger
    logger = logging.getLogger('simple_example')
    logger.setLevel(logging.DEBUG)

    # create console handler and set level to debug
    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)
    # create formatter for console handler
    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    # add formatter to console handler
    ch.setFormatter(formatter)

    # create file handler and set level to warn
    fh = logging.FileHandler('spam.log')
    fh.setLevel(logging.WARN)
    # create formatter for file handler
    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s')
    # add formatter to file handler
    fh.setFormatter(formatter)
    # add context filter to file handler
    fh.addFilter(ContextFilter())

    # add ch、fh to logger
    logger.addHandler(ch)
    logger.addHandler(fh)

    # 'application' code
    logger.debug('debug message')
    logger.info('info message')
    logger.warn('warn message %s', 'args')
    logger.error('error message')
    logger.critical('critical message')

　　console輸出結果：

2018-06-10 10:44:32,342 - simple_example - DEBUG - debug message
2018-06-10 10:44:32,342 - simple_example - INFO - info message
2018-06-10 10:44:32,342 - simple_example - WARNING - warn message args
2018-06-10 10:44:32,342 - simple_example - ERROR - error message
2018-06-10 10:44:32,342 - simple_example - CRITICAL - critical message

　　文件內容：

2018-06-10 10:44:32,342 - simple_example - WARNING - 123 - warn message args
2018-06-10 10:44:32,342 - simple_example - ERROR - 123 - error message
2018-06-10 10:44:32,342 - simple_example - CRITICAL - 123 - critical message

logging模塊解析

logger

　　logger是直接提供給應用程序使用的接口。一般來說，logging的其他幾個組件（Handler、Filter、Formatter）都是在初始化Logger的時候使用。

　　logger提供了以下API（部分、重要的）：

Logger.setLevel(level)
　　Sets the threshold for this logger to level. Logging messages which are less severe than level will be ignored.
Logger.isEnabledFor(lvl)
　　Indicates if a message of severity lvl would be processed by this logger. 
Logger.debug(msg, *args, **kwargs)
　　Logs a message with level DEBUG on this logger.

Logger.info(msg, *args, **kwargs)
　　Logs a message with level INFO on this logger.

Logger.warning(msg, *args, **kwargs)
　　Logs a message with level WARNING on this logger. same as Logger.warn

Logger.error(msg, *args, **kwargs)
　　Logs a message with level ERROR on this logger.

Logger.critical(msg, *args, **kwargs)
　　Logs a message with level CRITICAL on this logger. same as Logger.fatal

Logger.addFilter(filter)
　　Adds the specified filter filter to this logger.
Logger.removeFilter(filter)
　　Removes the specified filter filter from this logger.
Logger.addHandler(hdlr)
　　Adds the specified handler hdlr to this logger.
Logger.removeHandler(hdlr)
　　Removes the specified handler hdlr from this logger.　

logger實例

　　Logger對象不是通過實例化Logger而來的，都是通過 logging.get_logger(name)  獲得一個與name關聯的logger對象，logging內部會維護這個映射關系，用同樣的name反復調用logging.getLogger，事實上返回的是同一個對象。

Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

　　logger有一個父子關系，比如：

1 a_logger = logging.getLogger('A’） 
2 ab_logger = logging.getLogger('A.B’）

 　　通過name的層次關系就可以看出a_logger是ab_logger的parent。這個父子關系是會影響到日志的輸出的，后面介紹logging流程的時候可以看到。不過我並沒有使用過這種層級關系，所以本文也不會展開介紹。

log level

　　log level即日志的重要等級，意味着不同的緊急程度，不同的處理方式。python logging中，包含以下log level：

　　

　　上表也給出了什么時候使用什么級別的Log level的建議。

　　只有當寫日志時候的log level大於等於logger的level閾值(通過setLevel設置)時，日志才可能被輸出。

　　比如example1.py中，輸出到文件時，debug message、info message並沒有輸出，因為file handler的logger level是warning，DEBUG和INFO都小於WARNING。

FIlter && Handler

　　從logger中Filter、Handler相關的接口可以看到一個logger可以包含多個handler，多個Filter

　　在example1.py中，logger對象指定了兩個handler，第14行的StreamHandler，以及第16行的FileHandler。

Handler

　　Handler定義了如何處理一條日志，是本地打印，還是輸出到文件，還是通過網絡發送。

　　可以這么理解，日志代表的是一個事件（event），輸出日志的應用程序是生產者，而handler是消費者，消費者可以有多個。

　　Handler有以下API：

Handler.setLevel(level)
　　Sets the threshold for this handler to level. Logging messages which are less severe than level will be ignored. 
Handler.setFormatter(fmt)
　　Sets the Formatter for this handler to fmt.
Handler.addFilter(filter)
　　Adds the specified filter filter to this handler.
Handler.removeFilter(filter)
　　Removes the specified filter filter from this handler.

　　對於上述API，首先setFormatter表明了日志的格式，這里是“set”，而不是“add”，這個很好理解。其次，Handler有一些與Logger相同的函數：setLevel、addFilter、removeFilter。為啥要用相同的API，在tutorial中是這樣介紹的：

Why are there two setLevel() methods? The level set in the logger determines which severity of messages it will pass to its handlers. The level set in each handler determines which messages that handler will send on.

　　但個人認為這個解釋很牽強，我覺得在handler（日志事件的消費者）指定過濾條件更合理、更直觀。在生產者添加logLevel的目的只是為了開發調試方便：開發的時候通過debug輸出調試信息，開發的時候設置高於DEBUG的log level來避免輸出這些調試信息。

　　python logging提供了大量的實用的Handler，可以寫到標准輸出、文件、linux syslog、郵件、遠程服務器。

Formatter

responsible for converting a LogRecord to (usually) a string which can be interpreted by either a human or an external system　　

　　可以看到，Formatter將LogRecord輸出成字符串。應用程序每輸出一條日志的時候，就會創建一個LogRecord對象。看看上述例子：

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger.warn('warn message %s', 'args')

對應輸出： 
　　2018-06-10 10:44:32,342 - simple_example - WARNING - warn message args

　　可以看到，Formatter指定了輸出了格式與內容，在logger.warn的兩個輸入參數組成了formatter中的 %(message)s ，而formatter中的 %(asctime) 等則是在生成LogRecord填充

　　以下是默認提供的屬性：

　　

　　如果一個handler沒有指定Formatter，那么默認的formatter就是  logging.Formatter('%(message)s')  ，在上面的例子中，對於warn這條日志，那么輸出結果是 warn message args 

Filter

Filters can be used by Handlers and Loggers for more sophisticated filtering than is provided by levels.

filter(record)

　　Is the specified record to be logged? Returns zero for no, nonzero for yes. If deemed appropriate, the record may be modified in-place by this method.

　　Filter提供的是比log level更精確的過濾控制，只有當Filter.filter函數返回True的時候，這條日志才會被輸出。

　　由於Filter.filter函數的參數是LogRecord實例，那么可以修改LogRecord的屬性。在example1.py 第25行    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s')  file formatter中指定了屬性%(userid)s， 但userid並不在Formatter的屬性列表中，這個userid其實就是通過自定義的ContextFilter來實現的，在ContextFilter.filter中，給record對象添加了userid屬性。后面還會細講。

　　官方給出了很多例子，都是通過Filter來修改LogRecord的內容，來輸出一些上下文信息（contextual information）。但是我覺得這是一個不好的設計，顧名思義，Filter應該只做過濾的事情，理論上不應該修改輸入，builtin filter函數就是這樣的。

logging流程

　　從上述的介紹中可以看出，應用層打印的一條日志，需要經過很多步才能最終落地；既受到logger（生產者）的log level、Filter過濾，又要受到Handler（消費者）的log level、Filter過濾。

　　tutorial中給出了一個完整的流程圖：

　　

 

logging性能

lazy logging

　　在日志的藝術（The art of logging）一文中提到了lazy logging，即避免過早求值，把字符串的格式化推遲。但對於下面的語句

logger.debug('Message with %s, %s', expensive_func1(), expensive_func2())

　　雖然不會過早的字符串格式化（format），但是expensive_func1、expensive_func2這兩個函數一定會調用，不管日志是否會被輸出。如何避免調用這兩個函數，解決辦法是這樣的

if logger.isEnabledFor(logging.DEBUG):
    logger.debug('Message with %s, %s', expensive_func1(), expensive_func2())

　　即先判斷是否能夠輸出DEBUG等級的log，然后再調用logger.debug，這樣就避免了調用expensive_func1、expensive_func2這兩個函數

　　在這里，除了優化性能，還有一個好處就是讓代碼的意圖更加明顯（explicit），如果expensive_func是有副作用（side affect），即會改變某些內部狀態，那么用這樣的代碼能更清楚表達expensive_func 不一定會被調用。當然，寫在日志里面的表達式不應該有任何副作用、函數也應該是pure function。

性能開關

　　python logging模塊的性能是較差的，不僅僅是Python語言的問題，更多的是logging模塊的實現問題。

　　前面提到，應用程序的每一條日志都會生成一個LogRecord對象，然后Formatter將其轉換成string，怎么轉化的呢，其實核心就一句代碼  s = self._fmt % record.__dict__  self是Formatter實例，_fmt即初始化Formatter時傳入的參數，record即LogRecord實例。由於LogRecord不知道Formatter需要用到哪些屬性，所以干脆計算出所有的屬性（見圖一），這是eager evaluation，lazy evaluation應該更適合。

　　也許Formatter只用到了%(message)s 屬性，即只需要對logger.debug的輸入參數求值即可，但是LogRecord還是會去反復計算線程id、進程id、應用程序的調用信息（文件、函數、行號），這些都是很耗的操作。

　　對於部分確定不會用到的屬性，可以通過開關關掉：

What you don’t want to collect	How to avoid collecting it
Information about where calls were made from.	Set logging._srcfile to None. This avoids calling sys._getframe(), which may help to speed up your code in environments like PyPy (which can’t speed up code that uses sys._getframe()).
Threading information.	Set logging.logThreads to 0.
Process information.	Set logging.logProcesses to 0.

　　

　　通過下面的代碼測試（注釋第3到6行），關掉之后有25%左右的性能提升

import time
import logging
logging._srcfile = None
logging.logThreads = 0
logging.logMultiprocessing = 0
logging.logProcesses = 0

if __name__ == '__main__':
    logger = logging.getLogger('simple_example')
    logger.setLevel(logging.DEBUG)

    null = logging.NullHandler()
    logger.addHandler(null)

    begin = time.time()
    for i in xrange(100000):
        logger.debug('debug message')
        logger.info('info message')
        logger.warn('warn message')
        logger.error('error message')
        logger.critical('critical message')
    print 'cost', time.time() - begin

 

　　進一步，logging為了線程安全，每個Handler都會持有一個互斥鎖，每次寫日志的時候都會獲取鎖，寫完之后再釋放鎖。由於GIL的問題，多線程並不能給某些類型的python程序代碼性能提升。因此，如果應用程序能保證是單線程，那么可以設置  logging.thread = None  來避免使用鎖，簡單測試過也會有15%左右性能提升.

logging實用

　　再來看幾個logging使用方法或者技巧

同一個logger，不同的handler

　　在前面介紹logging.Logger的時候已經提到，一個logger（生產者）可以有多個handler（消費者）。不同的handler可以有不同的輸出格式（Formatter），不同的輸出過濾條件（level、Filter）。

　　比如對於線上項目，會有INFO、WARN、ERROR（FATAL）級別的日志產生。不同級別的日志待遇是不一樣的，INFO級別的日志，一般只會在查問題的時候用到，記錄到文件就行了；而WARN及以上級別的日志，就需要被監控系統采集、統計，會使用到SysLogHandler，然后配合ELK；而對於ERROR或者FATAL級別的日志，需要直接給值班賬號發郵件（短信）。

　　對於SyslogHandler，使用syslog_tag來設置分發方式是比較高效的，具體可見由一個簡單需求到Linux環境下的syslog、unix domain socket。需要注意的是，默認情況下每一個handler都會持有一個unix domain socket的文件描述符。

上下文信息（contextual information）

　　回到文章開始的問題，如何在日志中輸出必須的上下文信息，還是以用戶唯一標識（userid）為例。

　　要做到這個事情，有不同的策略。上策是自動化，自動輸出補全上下文信息；中策是檢測，如果不包含上下文信息，靜態代碼檢查或者運行時報錯；下策是強調，這個最不靠譜。

　　在前面已經提到，將LogRecord輸出成字符串核心就是   s = self._fmt % record.__dict__   ，_fmt是Formatter初始化格式，如果我們需要在_fmt中添加了自定義屬性，如userid，那么只需要保證record.__dict__中有 ‘userid’ 這個key就行了。

　　接下來看看具體的方法：

第一：使用Filter

　　如example2所示，直接在給record設置了userid屬性。

　　但使用Filter有一個缺點，不太靈活，Filter一般在初始化Logger（handler）的時候使用，但userid信息實在調用時才能明確的，而且顯然不會只有一個useid。

第二：使用extra參數

　　再來看看  Logger.debug(msg, *args, **kwargs) 

　　kwargs中可以包含兩個特殊的key：exc_info, extra。

The second keyword argument is extra which can be used to pass a dictionary which is used to populate the __dict__ of the LogRecord created for the logging event with user-defined attributes. These custom attributes can then be used as you like. For example, they could be incorporated into logged messages. 

　　具體怎么做到的？看源碼就很清楚了

def makeRecord(self, name, level, fn, lno, msg, args, exc_info, func=None, extra=None):
        """
        A factory method which can be overridden in subclasses to create
        specialized LogRecords.
        """
        rv = LogRecord(name, level, fn, lno, msg, args, exc_info, func)
        if extra is not None:
            for key in extra:
                if (key in ["message", "asctime"]) or (key in rv.__dict__):
                    raise KeyError("Attempt to overwrite %r in LogRecord" % key)
                rv.__dict__[key] = extra[key]
        return rv

 

　　在生成LogRecord的時候會直接把extra的值賦給LogRecord.__dict__.

　　因此，example2代碼可以改寫成這樣：

import logging

if __name__ == '__main__':
    # create logger
    logger = logging.getLogger('simple_example')
    logger.setLevel(logging.DEBUG)

    # create console handler and set level to debug
    ch = logging.StreamHandler()
    ch.setLevel(logging.DEBUG)
    # create formatter for console handler
    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    # add formatter to console handler
    ch.setFormatter(formatter)

    # create file handler and set level to warn
    fh = logging.FileHandler('spam.log')
    fh.setLevel(logging.WARN)
    # create formatter for file handler
    formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s')
    # add formatter to file handler
    fh.setFormatter(formatter)

    # add ch、fh to logger
    logger.addHandler(ch)
    logger.addHandler(fh)

    # 'application' code
    logger.debug('debug message', extra={'userid': '1'})
    logger.info('info message', extra={'userid': '2'})
    logger.warn('warn message %s', 'args', extra={'userid': '3'})
    logger.error('error message', extra={'userid': '4'})
    logger.critical('critical message', extra={'userid': '5'})

 

　　使用extra，比Filter更加靈活，每一條日志都可以根據實際情況指定不同的userid。但問題是每一條日志都需要寫額外的extra參數，既是在某些環節下extra參數內容都是一樣的。

　　當然，如果漏了extra，會報trace，也就是上面提到的中策的效果。

第三：使用LoggerAdapter

 　　使用LoggerAdapter避免了每條日志需要添加extra參數的問題，達到了上策的效果。LoggerAdapter實現很簡單，一看代碼就明白。

　　

class LoggerAdapter(object):
    def __init__(self, logger, extra):
        self.logger = logger
        self.extra = extra

    def process(self, msg, kwargs):
        """
        Process the logging message and keyword arguments passed in to
        a logging call to insert contextual information. You can either
        manipulate the message itself, the keyword args or both. Return
        the message and kwargs modified (or not) to suit your needs.
        Normally, you'll only need to override this one method in a
        LoggerAdapter subclass for your specific needs.
        """
        kwargs["extra"] = self.extra
        return msg, kwargs

    def debug(self, msg, *args, **kwargs):
        msg, kwargs = self.process(msg, kwargs)
        self.logger.debug(msg, *args, **kwargs)

 

　　直接使用LoggerAdapter.extra覆蓋掉kwargs['extra‘]，當然我覺得覆蓋並不是一個好主意，用update應該更合適。

　　假設類UserRequest處理用戶請求，那么每個UserRequest實例都持有一個   LoggerAdapter(logger, {'userid': realuserid})  ,這樣寫日志的時候就不會額外指定上下文信息（userid)了

 緩存日志內容，延遲輸出

　　來自cookbook buffering-logging-messages-and-outputting-them-conditionally

　　這是個非常有趣，且有用的想法。某些場景下，我們需要緩存一些日志，只有當滿足某些條件的時候再輸出。比如在線上查bug，需要加一些額外的調試（DEBUG或INFO）日志，但是只有當bug復現的情況下（ERROR日志標志問題復現了）才需要打印這些調試日志，因此可以先緩存，當出現了ERROR日志的時候再打印出所有的調試日志。

@log_if_errors(logger)
def foo(fail=False):

 

　　不過上面的例子只適合單個函數調用的情況，而實際環境中，查一個BUG可能需要追蹤的是一個調用流程。

總結

　　python logging模塊還有一些功能並未在文章介紹，比如豐富多樣的Handler，比如各種logger配置方式（除了在代碼中指定loglevel、formatter、filter，還可以寫配置文件，甚至從網絡讀取配置）。

　　python logging本身功能就有豐富，而且也比較好擴展，如果有什么需求，建議先好好看看文檔。

references

日志的藝術（The art of logging）

logging — Logging facility for Python

python logging tutorial

logging cookbook