python深入之日誌新增上下文資訊
除了傳遞給日誌記錄函式的引數（如msg）外，有時候我們還想在日誌輸出中包含一些額外的上下文資訊。比如，在一個網路應用中，可能希望在日誌中記錄客戶端的特定資訊，如：遠端客戶端的IP地址和使用者名稱。這裡我們來介紹以下幾種實現方式：
- 通過向日志記錄函式傳遞一個extra引數引入上下文資訊
- 使用LoggerAdapters引入上下文資訊
- 使用Filters引入上下文資訊
一、通過向日志記錄函式傳遞一個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數量變得不可控將會非常難以管理。
二、使用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必須是確定且明瞭的。
三、使用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中。