引入

最近工作上需要給自動測試框架添加一個新功能：根據線程來單獨記錄日誌。原有的框架中存在一個日誌模塊，其他模塊都通過它來記錄日誌，日誌分別會輸出到控制台和一個文件之中。假如主線程發起了一個或多個子線程，在該項新功能打開的情況下，子線程記錄的日誌會輸出到一個獨立的文件，且文件名與其他線程均不相同。實現的過程不算複雜，簡單講一講我的思路。

第一次寫技術文章， 定有不足之處，懇求斧正。我也希望知道這個做法是否符合最優實踐。

【感謝指出：

駱錚

這裡的dictionary線程安全有問題吧，儘管在Cpython下有GIL擦屁股但同時讀寫最好還是加個鎖？】

首先來看看Python的logging模塊。一般認為，使用logging模塊代替print是更好的實踐，程序員可以通過調節模塊的各項屬性來控制整個程序的日誌輸出。要使用該模塊，須先行配置根記錄器（rootlogger）。最簡單的方式：

import logginglogging.basicConfig(level=logging.DEBUG)

basicConfig()會做以下兩件事：

1. 添加默認的處理器

2. 添加默認的格式化器（formatter）

根記錄器的默認級別為「WARNING」。重要級別大於等於該等級的日誌才會被進一步處理。詳細的級別如下：

Level Numeric value

CRITICAL 50

ERROR 40

WARNING 30

INFO 20

DEBUG 10

NOTSET 0

通過 logging.getLogger(name)，我們可以獲得一個記錄器的實例。每一個記錄器與其名稱都是一對一的關係，傳入同樣的名字會得到同一個記錄器。如果不指定名稱（即name=』』），getLogger()將返回根記錄器。與根記錄器不同，其他記錄器的默認級別為「NOTSET」，若不做其他配置，日誌會被直接向上傳遞。在實踐中，通常的做法是在模塊級別獲取記錄器：

logging.getLogger(__name__)

日誌的向上傳遞

Python的logging模塊會對所有記錄器進行分層，記錄器之間可以存在父子關係。分層的標誌便是記錄器名稱中的「.」符號。比如，某記錄器的名稱為「foo」，「foo.bar」對應的就是其子記錄器。所有的一級記錄器均是根記錄器的子記錄器。

子記錄器的日誌在本層級處理後，會根據其propagate屬性的真與假繼續向上傳遞日誌或停止上傳。默認情況下，日誌是會層層上遞的，所有日誌最終都會被送到根記錄器。一般情況下只需要為各模塊獲取默認的記錄器，將記錄直接上傳，在日誌中顯示產生日誌的模塊名稱，就能比較好地分辨出日誌的來源。

處理器

在進行配置前，包括根記錄器在內的所有記錄器，都沒有任何處理器。然而，在未配置根記錄器的情況下調用logging模塊自身的記錄方法（logging.debug()、logging.warning()等等），basicConfig()也會被調用，對根記錄器加上一個預設的StreamHandler。每一個處理器均會將日誌輸出至某一目標（流或文件）。根據處理器（handler）的不同，同一條日誌可以用不同的格式分別輸出。因此，在設置多個處理器時，必須考慮清楚是否會有重複記錄的可能。這也是我自己在應用過程中被坑了好幾次的地方，曾經用了不少時間調試同一條日誌反覆出現的「bug」。

Logging模塊自帶常用的處理器，可以滿足絕大多數情況下的需求。接下來我們會用到的有StreamHandler和RotatingFileHandler。前者將日誌輸出到流（stdout或stderr）。後者將日誌輸出到文件，還能夠設置單個文件大小的上限，接近上限時，處理器會開啟一個新文件繼續記錄。常見的日誌文件形式「xxx.1.log」「xxx.2.log」等等就是滾動記錄文件的例子。

要添加處理器，調用記錄器的addHandler()並傳入一個處理器實例即可。

過濾器

過濾器（filter）用於接受或拒絕傳遞到記錄器或處理器中的日誌。雖然Python3.2之後filter不一定非要用類來實現，但為了向下兼容，還是寫一個包含filter()方法的類更好。

filter()方法接收一個參數record，即一條日誌記錄。該方法返回0表示拒絕記錄，返回非0則接受。需要注意的是，記錄器的過濾器不會對其子記錄器傳遞上來的日誌進行過濾，而只對自身記錄的日誌進行過濾。我們通過一段代碼來演示這條規則：

>>> child.error(error)ERROR:parent.child:error>>> parent.error(error)>>> parent.critical(critical)CRITICAL:parent:critical>>>

在本例中，只有根記錄器進行了處理器的配置。parent.child記錄器會將「WARNING」級別以下的日誌過濾掉，parent的過濾器只讓「CRITICAL」及以上的日誌通過。可以看到，parent本身記錄的ERROR級別的日誌並未輸出，但從child傳遞上來的error日誌並未被過濾，而是繼續上傳到根記錄器進行輸出。

要添加過濾器，調用記錄器或處理器的addFilter()並傳入一個過濾器的實例即可。

分線程進行記錄

默認情況下，如果只設置一個輸出到文件的處理器，所有線程產生的日誌都會被放到同一個文件之中。由於子線程的啟動是在程序開始執行後發生的，為了實現不同線程的日誌輸出到不同的文件，我們可以有以下兩種思路。

一是繼承logging模塊自帶的FileHandler，重載出一個根據當前調用線程改變輸出文件目標的處理器類。這是我首先想到的，但在看過FileHandler的源碼後發現需要做的改動較大。該類的目標文件流在初始化的時候就已經設置好，且打開文件的open()方法只會打開並保存一個文件流。如果要讓一個處理器同時操作多個文件，就要自己改寫open()方法，將打開的流緩存起來以避免頻繁地打開、關閉文件。

二是將每一個線程與一個記錄器綁定，記錄器的名稱為「主線程ID.子線程ID」（注意中間用於分隔的點符號）。在調用記錄器時，模塊將會根據線程ID從主類的字典中找到對應的記錄器並返回。如果沒有找到，就調用設置方法來初始化一個新的記錄器並放入字典中緩存起來。這個思路的優點是將更基本的操作（打開、關閉文件流等）交給logging模塊，我們只需要關註上層的邏輯實現，且每一個記錄器都保有自己的文件流，在程序結束前只需要進行一次打開文件的動作。程序執行完畢後，logging模塊會負責清理。同時，由於應用了記錄器的層級關係，我們可以對日誌流有更好的控制。

考慮過後，我最終選擇了第二種方式。另外，因為日誌模塊要被其他模塊調用，是日誌的唯一出口，其主類會做成單例（singleton）以避免重複初始化。無論是否使用分線程記錄功能，各線程都有其獨立的輸出文件，所以不用考慮線程安全的問題。

在這個設計中，所有的日誌將會被向上傳遞到根記錄器。對於每一條記錄，我們只需要向控制台（stdout或者stderr）輸出一次，故只對根記錄器添加處理器：

def __init__(self, level=LOG_LEVEL_DEBUG, log_by_thread=False, log_path=, max_bytes=0, backup_count=0): # set root logger logging.getLogger().setLevel(LOG_LEVEL_NOTSET) logging.getLogger().addHandler(HandlerFactory.get_std_out_handler()) logging.getLogger().addHandler(HandlerFactory.get_std_err_handler()) # default logger setting logger.info("General logger initializing...") self._loggers = {} self._log_level = level self._main_thread_id = str(self.get_current_thread_id()) self._log_destination = LOG_TARGET_CONSOLE self._log_by_thread = log_by_thread self._log_path = log_path self._log_file_max_bytes = max_bytes self._log_file_backup_count = backup_count

對於這個模塊本身，我們也獲取一個以文件名命名的記錄器，用於主類內部的日誌記錄。

生成處理器

雖然只對根記錄器添加處理器，我還是將生成處理器的函數放進了HandlerFactory這個類中，所有生成的處理器均會被緩存起來，以備調用。

class HandlerFactory(object): handlers = {} @classmethod def get_std_out_handler(cls): if std_out_handler not in cls.handlers: std_out_handler = logging.StreamHandler(sys.stdout) std_out_handler.setFormatter(logging.Formatter(_LOGGER_FORMAT)) std_out_handler.addFilter(InfoOrLessCritical()) cls.handlers[std_out_handler] = std_out_handler return cls.handlers[std_out_handler]

這裡我們設置一個格式化的、只處理重要級別低於「WARNING」的處理器，日誌將被輸出到標準流。我們可以根據需求，寫出不同的處理器對日誌進行不同的操作 。

設置、獲得主線程及子線程的記錄器

在每一次進行記錄日誌時，模塊都會獲取相應的記錄器。這樣我們就可以根據當前線程來設定記錄器的處理器，將日誌輸出到不同的文件之中。如果該線程未獲取過記錄器，模塊會進行設置：

def set_logger(self, name): if name not in self._loggers: new_logger = logging.getLogger(name) new_logger.setLevel(self._log_level) if self._log_path: # log path will vary if log by thread is enabled log_path = self.get_log_file_name() new_logger.addHandler(HandlerFactory.get_rotating_file_handler( log_path, self._log_file_max_bytes, self._log_file_backup_count)) self._loggers[name] = new_logger

在get_logger()方法中，模塊會以線程ID為名稱，給所有線程的記錄器命名，並建立子線程記錄器與主線程記錄器之間的層級關係。

測試結果

這裡我設置了兩條線程分別輸出日誌，在分線程記錄打開的情況下，子線程的日誌會輸出到單獨的文件中。

if __name__ == __main__: def worker(message): worker_logger = GeneralLogger().get_logger() worker_logger.info(message + info) worker_logger.debug(message + debug) worker_logger.warning(message + warning) worker_logger.error(message + error) GeneralLogger().set_log_path(/tmp/test.txt) GeneralLogger().set_log_by_thread_log(True) GeneralLogger().set_log_level(LOG_LEVEL_DEBUG) main_logger = GeneralLogger().get_logger() main_logger.debug(debug) main_logger.warning(warning) main_logger.info(info) main_logger.error(error) t1 = threading.Thread(target=worker, args=(worker 1,)) t2 = threading.Thread(target=worker, args=(worker 2,)) t1.start() t2.start()

kagami@ip-:~/self-library/Python$ python logger.py[ INFO] [2016-07-0222:54:56,478] [140278750246720] [logger] - General logger initializing...[ DEBUG] [2016-07-0222:54:56,478] [140278750246720] [logger] - debug[WARNING] [2016-07-02 22:54:56,478] [140278750246720][logger] - warning[ INFO] [2016-07-0222:54:56,479] [140278750246720] [logger] - info[ ERROR] [2016-07-0222:54:56,479] [140278750246720] [logger] - error[ INFO] [2016-07-0222:54:56,479] [140278721500928] [logger] - worker 1 info[ DEBUG] [2016-07-0222:54:56,479] [140278721500928] [logger] - worker 1 debug[WARNING] [2016-07-02 22:54:56,480] [140278721500928][logger] - worker 1 warning[ ERROR] [2016-07-0222:54:56,480] [140278721500928] [logger] - worker 1 error[ INFO] [2016-07-0222:54:56,480] [140278713108224] [logger] - worker 2 info[ DEBUG] [2016-07-0222:54:56,480] [140278713108224] [logger] - worker 2 debug[WARNING] [2016-07-02 22:54:56,481] [140278713108224][logger] - worker 2 warning[ ERROR] [2016-07-0222:54:56,481] [140278713108224] [logger] - worker 2 error

kagami@ip-:/tmp$ cat 140278750246720_MainThread_test.txt[ DEBUG] [2016-07-02 22:54:56,478] [140278750246720] [logger] - debug[WARNING] [2016-07-02 22:54:56,478] [140278750246720] [logger] - warning[ INFO] [2016-07-02 22:54:56,479] [140278750246720] [logger] - info[ ERROR] [2016-07-02 22:54:56,479] [140278750246720] [logger] - error[ INFO] [2016-07-02 22:54:56,479] [140278721500928] [logger] - worker 1 info[ DEBUG] [2016-07-02 22:54:56,479] [140278721500928] [logger] - worker 1 debug[WARNING] [2016-07-02 22:54:56,480] [140278721500928] [logger] - worker 1 warning[ ERROR] [2016-07-02 22:54:56,480] [140278721500928] [logger] - worker 1 error[ INFO] [2016-07-02 22:54:56,480] [140278713108224] [logger] - worker 2 info[ DEBUG] [2016-07-02 22:54:56,480] [140278713108224] [logger] - worker 2 debug[WARNING] [2016-07-02 22:54:56,481] [140278713108224] [logger] - worker 2 warning[ ERROR] [2016-07-02 22:54:56,481] [140278713108224] [logger] - worker 2 error

kagami@ip-:/tmp$ cat 140278721500928_Thread-1_test.txt[ INFO] [2016-07-02 22:54:56,479] [140278721500928] [logger] - worker 1 info[ DEBUG] [2016-07-02 22:54:56,479] [140278721500928] [logger] - worker 1 debug[WARNING] [2016-07-02 22:54:56,480] [140278721500928] [logger] - worker 1 warning[ ERROR] [2016-07-02 22:54:56,480] [140278721500928] [logger] - worker 1 error

kagami@ip-:/tmp$ cat 140278713108224_Thread-2_test.txt[ INFO] [2016-07-02 22:54:56,480] [140278713108224] [logger] - worker 2 info[ DEBUG] [2016-07-02 22:54:56,480] [140278713108224] [logger] - worker 2 debug[WARNING] [2016-07-02 22:54:56,481] [140278713108224] [logger] - worker 2 warning[ ERROR] [2016-07-02 22:54:56,481] [140278713108224] [logger] - worker 2 error

結語

正如我在開頭所說的，整個思路其實非常簡單。關鍵是弄清楚Python的logging模塊如何處理日誌、處理器怎麼輸出。我先前也遇到過一些問題，但沒有深入了解。這次乾脆認真點將logging模塊的文檔讀了一遍，將心得寫下來和大家分享。

最後貼一張官方文檔中的圖表，整個流程一目了然：

https://docs.python.org/3/howto/logging.html#logging-flow

推薦閱讀

Logging HOWTO: https://docs.python.org/3/howto/logging.html

Good logging practice in Python: http://victorlin.me/posts/2012/08/26/good-logging-practice-in-python

推薦閱讀：