Python之向日志輸出中添加上下文信息

除了傳遞給日誌記錄函數的參數（如msg）外，有時候咱們還想在日誌輸出中包含一些額外的上下文信息。好比，在一個網絡應用中，可能但願在日誌中記錄客戶端的特定信息，如：遠程客戶端的IP地址和用戶名。這裏咱們來介紹如下幾種實現方式：

• 經過向日志記錄函數傳遞一個extra參數引入上下文信息
• 使用LoggerAdapters引入上下文信息
• 使用Filters引入上下文信息

1、經過向日志記錄函數傳遞一個extra參數引入上下文信息

---

前面咱們提到過，能夠經過向日志記錄函數傳遞一個extra參數來實現向日志輸出中添加額外的上下文信息，如：

import logging
import sys

fmt = logging.Formatter("%(asctime)s - %(name)s - %(ip)s - %(username)s - %(message)s")
h_console = logging.StreamHandler(sys.stdout)
h_console.setFormatter(fmt)
logger = logging.getLogger("myPro")
logger.setLevel(logging.DEBUG)
logger.addHandler(h_console)

extra_dict = {"ip": "113.208.78.29", "username": "Petter"}
logger.debug("User Login!", extra=extra_dict)

extra_dict = {"ip": "223.190.65.139", "username": "Jerry"}
logger.info("User Access!", extra=extra_dict)

輸出：

2017-05-14 15:47:25,562 - myPro - 113.208.78.29 - Petter - User Login!
2017-05-14 15:47:25,562 - myPro - 223.190.65.139 - Jerry - User Access!

可是用這種方式來傳遞信息並非那麼方便，由於每次調用日誌記錄方法都要傳遞一個extra關鍵詞參數。即使沒有須要插入的上下文信息也是如此，由於該logger設置的formatter格式中指定的字段必需要存在。因此，咱們推薦使用下面兩種方式來實現上下文信息的引入。

也許能夠嘗試建立許多不一樣的Logger實例來解決上面存在的問題，可是這顯然不是一個好的解決方案，由於這些Logger實例並不會進行垃圾回收。儘管這在實踐中不是個問題，可是當Logger數量變得不可控將會很是難以管理。

2、使用LoggerAdapters引入上下文信息

---

使用LoggerAdapter類來傳遞上下文信息到日誌事件的信息中是一個很是簡單的方式，能夠把它看作第一種實現方式的優化版--由於它爲extra提供了一個默認值。這個類設計的相似於Logger，所以咱們能夠像使用Logger類的實例那樣來調用debug(), info(), warning(),error(), exception(), critical()和log()方法。當建立一個LoggerAdapter的實例時，咱們須要傳遞一個Logger實例和一個包含上下文信息的類字典對象給該類的實例構建方法。當調用LoggerAdapter實例的一個日誌記錄方法時，該方法會在對日誌日誌消息和字典對象進行處理後，調用構建該實例時傳遞給該實例的logger對象的同名的日誌記錄方法。下面是LoggerAdapter類中幾個方法的定義：

class LoggerAdapter(object):
    """
    An adapter for loggers which makes it easier to specify contextual
    information in logging output.
    """

    def __init__(self, logger, extra):
        """
        Initialize the adapter with a logger and a dict-like object which
        provides contextual information. This constructor signature allows
        easy stacking of LoggerAdapters, if so desired.

        You can effectively pass keyword arguments as shown in the
        following example:

        adapter = LoggerAdapter(someLogger, dict(p1=v1, p2="v2"))
        """
        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):
        """
        Delegate a debug call to the underlying logger, after adding
        contextual information from this adapter instance.
        """
        msg, kwargs = self.process(msg, kwargs)
        self.logger.debug(msg, *args, **kwargs)

經過分析上面的代碼能夠得出如下結論：

• 上下文信息是在LoggerAdapter類的process()方法中被添加到日誌記錄的輸出消息中的，若是要實現自定義需求只須要實現LoggerAdapter的子類並重寫process()方法便可；
• process()方法的默認實現中，沒有修改msg的值，只是爲關鍵詞參數插入了一個名爲extra的 key，這個extra的值爲傳遞給LoggerAdapter類構造方法的參數值；
• LoggerAdapter類構建方法所接收的extra參數，實際上就是爲了知足logger的formatter格式要求所提供的默認上下文信息。

關於上面提到的第3個結論，咱們來看個例子：

import logging
import sys


# 初始化一個要傳遞給LoggerAdapter構造方法的logger實例
fmt = logging.Formatter("%(asctime)s - %(name)s - %(ip)s - %(username)s - %(message)s")
h_console = logging.StreamHandler(sys.stdout)
h_console.setFormatter(fmt)
init_logger = logging.getLogger("myPro")
init_logger.setLevel(logging.DEBUG)
init_logger.addHandler(h_console)

# 初始化一個要傳遞給LoggerAdapter構造方法的上下文字典對象
extra_dict = {"ip": "IP", "username": "USERNAME"}

# 獲取一個LoggerAdapter類的實例
logger = logging.LoggerAdapter(init_logger, extra_dict)

# 應用中的日誌記錄方法調用
logger.info("User Login!")
logger.info("User Login!", extra={"ip": "113.208.78.29", "username": "Petter"})
logger.extra = {"ip": "113.208.78.29", "username": "Petter"}
logger.info("User Login!")
logger.info("User Login!")

輸出結果：

# 使用extra默認值：{"ip": "IP", "username": "USERNAME"}
2017-05-14 17:23:15,148 - myPro - IP - USERNAME - User Login!

# info(msg, extra)方法中傳遞的extra方法沒有覆蓋默認值
2017-05-14 17:23:15,148 - myPro - IP - USERNAME - User Login!

# extra默認值被修改了
2017-05-14 17:23:15,148 - myPro - 113.208.78.29 - Petter - User Login!
2017-05-14 17:23:15,148 - myPro - 113.208.78.29 - Petter - User Login!

根據上面的程序輸出結果，咱們會發現一個問題：傳遞給LoggerAdapter類構造方法的extra參數值不能被LoggerAdapter實例的日誌記錄函數（如上面調用的info()方法）中的extra參數覆蓋，只能經過修改LoggerAdapter實例的extra屬性來修改默認值（如上面使用的logger.extra=xxx），可是這也就意味着默認值被修改了。

解決這個問題的思路應該是：實現一個LoggerAdapter的子類，重寫process()方法。其中對於kwargs參數的操做應該是先判斷其自己是否包含extra關鍵字，若是包含則不使用默認值進行替換；若是kwargs參數中不包含extra關鍵字則取默認值。來看具體實現：

import logging
import sys

class MyLoggerAdapter(logging.LoggerAdapter):

    def process(self, msg, kwargs):
        if 'extra' not in kwargs:
            kwargs["extra"] = self.extra
        return msg, kwargs

if __name__ == '__main__':
    # 初始化一個要傳遞給LoggerAdapter構造方法的logger實例
    fmt = logging.Formatter("%(asctime)s - %(name)s - %(ip)s - %(username)s - %(message)s")
    h_console = logging.StreamHandler(sys.stdout)
    h_console.setFormatter(fmt)
    init_logger = logging.getLogger("myPro")
    init_logger.setLevel(logging.DEBUG)
    init_logger.addHandler(h_console)
    
    # 初始化一個要傳遞給LoggerAdapter構造方法的上下文字典對象
    extra_dict = {"ip": "IP", "username": "USERNAME"}
    
    # 獲取一個自定義LoggerAdapter類的實例
    logger = MyLoggerAdapter(init_logger, extra_dict)
    
    # 應用中的日誌記錄方法調用
    logger.info("User Login!")
    logger.info("User Login!", extra={"ip": "113.208.78.29", "username": "Petter"})
    logger.info("User Login!")
    logger.info("User Login!")

輸出結果：

# 使用extra默認值：{"ip": "IP", "username": "USERNAME"}
2017-05-22 17:35:38,499 - myPro - IP - USERNAME - User Login!

# info(msg, extra)方法中傳遞的extra方法已覆蓋默認值
2017-05-22 17:35:38,499 - myPro - 113.208.78.29 - Petter - User Login!

# extra默認值保持不變
2017-05-22 17:35:38,499 - myPro - IP - USERNAME - User Login!
2017-05-22 17:35:38,499 - myPro - IP - USERNAME - User Login!

OK！ 問題解決了。

其實，若是咱們想不受formatter的限制，在日誌輸出中實現自由的字段插入，能夠經過在自定義LoggerAdapter的子類的process()方法中將字典參數中的關鍵字信息拼接到日誌事件的消息中。很明顯，這些上下文中的字段信息在日誌輸出中的位置是有限制的。而使用'extra'的優點在於，這個類字典對象的值將被合併到這個LogRecord實例的__dict__中，這樣就容許咱們經過Formatter實例自定義日誌輸出的格式字符串。這雖然使得上下文信息中的字段信息在日誌輸出中的位置變得與內置字段同樣靈活，可是前提是傳遞給構造器方法的這個類字典對象中的key必須是肯定且明瞭的。

3、使用Filters引入上下文信息

---

另外，咱們還可使用自定義的Filter.Filter實例的方式，在filter(record)方法中修改傳遞過來的LogRecord實例，把要加入的上下文信息做爲新的屬性賦值給該實例，這樣就能夠經過指定formatter的字符串格式來輸出這些上下文信息了。

咱們模仿上面的實現，在傳遞個filter(record)方法的LogRecord實例中添加兩個與當前網絡請求相關的信息：ip和username。

import logging
from random import choice


class ContextFilter(logging.Filter):

        ip = 'IP'
        username = 'USER'

        def filter(self, record):
            record.ip = self.ip
            record.username = self.username
            return True

if __name__ == '__main__':
    levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
    users = ['Tom', 'Jerry', 'Peter']
    ips = ['113.108.98.34', '219.238.78.91', '43.123.99.68']

    logging.basicConfig(level=logging.DEBUG,
                        format='%(asctime)-15s %(name)-5s %(levelname)-8s %(ip)-15s %(username)-8s %(message)s')
    logger = logging.getLogger('myLogger')
    filter = ContextFilter()
    logger.addFilter(filter)
    logger.debug('A debug message')
    logger.info('An info message with %s', 'some parameters')

    for x in range(5):
        lvl = choice(levels)
        lvlname = logging.getLevelName(lvl)
        filter.ip = choice(ips)
        filter.username = choice(users)
        logger.log(lvl, 'A message at %s level with %d %s' , lvlname, 2, 'parameters')

輸出結果：

2017-05-15 10:21:49,401 myLogger DEBUG    IP              USER     A debug message
2017-05-15 10:21:49,401 myLogger INFO     IP              USER     An info message with some parameters
2017-05-15 10:21:49,401 myLogger INFO     219.238.78.91   Tom      A message at INFO level with 2 parameters
2017-05-15 10:21:49,401 myLogger INFO     219.238.78.91   Peter    A message at INFO level with 2 parameters
2017-05-15 10:21:49,401 myLogger DEBUG    113.108.98.34   Jerry    A message at DEBUG level with 2 parameters
2017-05-15 10:21:49,401 myLogger CRITICAL 43.123.99.68    Tom      A message at CRITICAL level with 2 parameters
2017-05-15 10:21:49,401 myLogger INFO     43.123.99.68    Jerry    A message at INFO level with 2 parameters

須要說明的是： 實際的網絡應用程序中，可能還要考慮多線程併發時的線程安全問題，此時能夠把鏈接信息或者自定義過濾器的實例經過threading.local保存到到一個threadlocal中。

• 參考文檔：https://docs.python.org/3.5/howto/logging-cookbook.html#adding-contextual-information-to-your-logging-output

  問題交流羣：666948590