編譯： Python開(kāi)發(fā)者 - 李趴趴要化身女超人，英文：Mario Corchero

http://python./89007/

對(duì)一名開(kāi)發(fā)者來(lái)說(shuō)最糟糕的情況，莫過(guò)于要弄清楚一個(gè)不熟悉的應(yīng)用為何不工作。有時(shí)候，你甚至不知道系統(tǒng)運(yùn)行，是否跟原始設(shè)計(jì)一致。

在線(xiàn)運(yùn)行的應(yīng)用就是黑盒子，需要被跟蹤監(jiān)控。最簡(jiǎn)單也最重要的方式就是記錄日志。記錄日志允許我們?cè)陂_(kāi)發(fā)軟件的同時(shí)，讓程序在系統(tǒng)運(yùn)行時(shí)發(fā)出信息，這些信息對(duì)于我們和系統(tǒng)管理員來(lái)說(shuō)都是有用的。

就像為將來(lái)的程序員寫(xiě)代碼文檔一樣，我們應(yīng)該讓新軟件產(chǎn)生足夠的日志供系統(tǒng)的開(kāi)發(fā)者和管理員使用。日志是關(guān)于應(yīng)用運(yùn)行狀態(tài)的系統(tǒng)文件的關(guān)鍵部分。給軟件加日志產(chǎn)生句時(shí)，要向給未來(lái)維護(hù)系統(tǒng)的開(kāi)發(fā)者和管理員寫(xiě)文檔一樣。

一些純粹主義者認(rèn)為一個(gè)受過(guò)訓(xùn)練的開(kāi)發(fā)者使用日志和測(cè)試的時(shí)候幾乎不需要交互調(diào)試器。如果我們不能用詳細(xì)的日志解釋開(kāi)發(fā)過(guò)程中的應(yīng)用，那么當(dāng)代碼在線(xiàn)上運(yùn)行的時(shí)候，解釋它們會(huì)變得更困難。

這篇文章介紹了 Python 的 logging 模塊，包括它的設(shè)計(jì)以及針對(duì)更多復(fù)雜案例的適用方法。這篇文章不是寫(xiě)給開(kāi)發(fā)者的文檔，它更像是一個(gè)指導(dǎo)手冊(cè)，來(lái)說(shuō)明 Python 的 logging 模板是如何搭建的，并且激發(fā)感興趣的人深入研究。

為什么使用 logging 模塊？

也許會(huì)有開(kāi)發(fā)者會(huì)問(wèn)，為什么不是簡(jiǎn)單的 print 語(yǔ)句呢？ Logging 模塊有很多優(yōu)勢(shì)，包括：

1. 多線(xiàn)程支持

2. 通過(guò)不同級(jí)別的日志分類(lèi)

3. 靈活性和可配置性

4. 將如何記錄日志與記錄什么內(nèi)容分離

最后一點(diǎn)，將我們記錄內(nèi)容從記錄方式中真正分離，保證了軟件不同部分的合作。舉個(gè)例子，它允許一個(gè)框架或庫(kù)的開(kāi)發(fā)者增加日志并且讓系統(tǒng)管理員或負(fù)責(zé)運(yùn)行配置的人員決定稍后應(yīng)該記錄什么。

Logging 模塊中有什么

Logging 模塊完美地將它的每個(gè)部分的職責(zé)分離（遵循 Apache Log4j API 的方法）。讓我們看看一個(gè)日志線(xiàn)是如何通過(guò)這個(gè)模塊的代碼，并且研究下它的不同部分。

記錄器（Logger）

記錄器是開(kāi)發(fā)者經(jīng)常交互的對(duì)象。那些主要的 API 說(shuō)明了我們想要記錄的內(nèi)容。

舉個(gè)記錄器的例子，我們可以分類(lèi)請(qǐng)求發(fā)出一條信息，而不用擔(dān)心它們是如何從哪里被發(fā)出的。

比如，當(dāng)我們寫(xiě)下 logger.info(“Stock was sold at %s”, price) 我們?cè)陬^腦中就有如下模塊：

我們需要一條線(xiàn)。假設(shè)有些代碼在記錄器中運(yùn)行，讓這條線(xiàn)出現(xiàn)在控制臺(tái)或文件中。但是在內(nèi)部實(shí)際發(fā)生了什么呢？

日志記錄

日志記錄是 logging 模塊用來(lái)滿(mǎn)足所有需求信息的包。它們包含了需要記錄日志的地方、變化的字符串、參數(shù)、請(qǐng)求的信息隊(duì)列等信息。

它們都是被記錄的對(duì)象。每次我們調(diào)用記錄器時(shí)，都會(huì)生成這些對(duì)象。但這些對(duì)象是如何序列化到流中的呢？通過(guò)處理器！

處理器

處理器將日志記錄發(fā)送給其他輸出終端，他們獲取日志記錄并用相關(guān)函數(shù)中處理它們。

比如，一個(gè)文件處理器將會(huì)獲取一條日志記錄，并且把它添加到文件中。

標(biāo)準(zhǔn)的 logging 模塊已經(jīng)具備了多種內(nèi)置的處理器，例如：

多種文件處理器（TimeRotated, SizeRotated, Watched），可以寫(xiě)入文件中

1. StreamHandler 輸出目標(biāo)流比如 stdout 或 stderr

2. SMTPHandler 通過(guò) email 發(fā)送日志記錄

3. SocketHandler 將日志文件發(fā)送到流套接字

4. SyslogHandler、NTEventHandler、HTTPHandler及MemoryHandler等

目前我們有個(gè)類(lèi)似于真實(shí)情況的模型：

大部分的處理器都在處理字符串(SMTPHandler和FileHandler等)。或許你想知道這些結(jié)構(gòu)化的日志記錄是如何轉(zhuǎn)變?yōu)橐子谛蛄谢淖止?jié)的。

格式器

格式器負(fù)責(zé)將豐富的元數(shù)據(jù)日志記錄轉(zhuǎn)換為字符串，如果什么都沒(méi)有提供，將會(huì)有個(gè)默認(rèn)的格式器。

一般的格式器類(lèi)由 logging 庫(kù)提供，采用模板和風(fēng)格作為輸入。然后占位符可以在一個(gè) LogRecord 對(duì)象中聲明所有屬性。

比如：’%(asctime)s %(levelname)s %(name)s: %(message)s’ 將會(huì)生成日志類(lèi)似于 2017-07-19 15:31:13,942 INFO parent.child: Hello EuroPython.

請(qǐng)注意：屬性信息是通過(guò)提供的參數(shù)對(duì)日志的原始模板進(jìn)行插值的結(jié)果。（比如，對(duì)于 logger.info(“Hello %s”, “Laszlo”) 這條信息將會(huì)是 “Hello Laszlo”）

所有默認(rèn)的屬性都可以在日志文檔中找到。

好了，現(xiàn)在我們了解了格式器，我們的模型又發(fā)生了變化：

過(guò)濾器

我們?nèi)罩竟ぞ叩淖詈笠粋€(gè)對(duì)象就是過(guò)濾器。

過(guò)濾器允許對(duì)應(yīng)該發(fā)送的日志記錄進(jìn)行細(xì)粒度控制。多種過(guò)濾器能同時(shí)應(yīng)用在記錄器和處理器中。對(duì)于一條發(fā)送的日志來(lái)說(shuō)，所有的過(guò)濾器都應(yīng)該通過(guò)這條記錄。

用戶(hù)可以聲明他們自己的過(guò)濾器作為對(duì)象，使用 filter 方法獲取日志記錄作為輸入，反饋 True / False 作為輸出。

出于這種考慮，以下是當(dāng)前的日志工作流：

記錄器層級(jí)

此時(shí)，你可能會(huì)對(duì)大量復(fù)雜的內(nèi)容和巧妙隱藏的模塊配置印象深刻，但是還有更需要考慮的：記錄器分層。

我們可以通過(guò) logging.getLogger() 創(chuàng)建一個(gè)記錄器。這條字符向 getLogger 傳遞了一個(gè)參數(shù)，這個(gè)參數(shù)可以通過(guò)使用圓點(diǎn)分隔元素來(lái)定義一個(gè)層級(jí)。

舉個(gè)例子，logging.getLogger(“parent.child”) 將會(huì)創(chuàng)建一個(gè) “child” 的記錄器，它的父級(jí)記錄器叫做 “parent.” 記錄器是被 logging 模塊管理的全局對(duì)象，所以我們可以方便地在項(xiàng)目中的任何地方檢索他們。

記錄器的例子通常也被認(rèn)為是渠道。層級(jí)允許開(kāi)發(fā)者去定義渠道和他們的層級(jí)。

在日志記錄被傳遞到所有記錄器內(nèi)的處理器時(shí)，父級(jí)處理器將會(huì)進(jìn)行遞歸處理，直到我們到達(dá)頂級(jí)的記錄器（被定義為一個(gè)空字符串），或者有一個(gè)記錄器設(shè)置了 propagate = False。我們可通過(guò)更新的圖中看出：

請(qǐng)注意父級(jí)記錄器沒(méi)有被調(diào)用，只有它的處理器被調(diào)用。這意味著過(guò)濾器和其他在記錄器類(lèi)中的代碼不會(huì)在父級(jí)中被執(zhí)行。當(dāng)我們?cè)谟涗浧髦性黾舆^(guò)濾器時(shí)，這通常是個(gè)陷阱。

工作流小結(jié)

我們已經(jīng)闡明過(guò)職責(zé)的劃分以及我們是如何微調(diào)日志過(guò)濾。然而還是有兩個(gè)其他的屬性我們沒(méi)有提及：

1. 記錄器可以是殘缺的，從而不允許任何記錄從這被發(fā)出。

2. 一個(gè)有效的層級(jí)可以同時(shí)在記錄器和處理器中被設(shè)置。

舉個(gè)例子，當(dāng)一個(gè)記錄器被設(shè)置為 INFO 的等級(jí)，只有 INFO 等級(jí)及以上的才會(huì)被傳遞，同樣的規(guī)則適用于處理器。

基于以上所有的考慮，最后的日志記錄的流程圖看起來(lái)像這樣：

如何使用日志記錄模塊

現(xiàn)在我們已經(jīng)了解了 logging 模塊的部分及設(shè)計(jì)，是時(shí)候去了解一個(gè)開(kāi)發(fā)者是如何與它交互的了。以下是一個(gè)代碼例子：

import logging

 

def sample_function(secret_parameter):

    logger = logging.getLogger(__name__)  # __name__=projectA.moduleB

    logger.debug('Going to perform magic with '%s'',  secret_parameter)

    ...

    try:

        result = do_magic(secret_parameter)

    except IndexError:

        logger.exception('OMG it happened again, someone please tell Laszlo')

    except:

        logger.info('Unexpected exception', exc_info=True)

        raise

    else:

        logger.info('Magic with '%s' resulted in '%s'', secret_parameter, result, stack_info=True)

它用模塊 __name__ 創(chuàng)建了一個(gè)日志記錄器。它會(huì)基于項(xiàng)目結(jié)構(gòu)創(chuàng)建渠道和等級(jí)，正如 Pyhon 模塊用圓點(diǎn)連接一樣。

記錄器變量引用記錄器的 “module” ，用 “projectA” 作為父級(jí)， “root” 作為父級(jí)的父級(jí)。

在第五行，我們看到如何執(zhí)行調(diào)用去發(fā)送日志。我們可以用 debug 、 info 、error 或 critical 這些方法之一在合適的等級(jí)上去記錄日志。

當(dāng)記錄一條信息時(shí)，除了模板參數(shù)，我們可以通過(guò)特殊的含義傳遞密碼參數(shù)，最有意思的是 exc_info 和 stack_info。它們將會(huì)分別增加關(guān)于當(dāng)前異常和棧幀的信息。為了方便起見(jiàn)，在記錄器對(duì)象中有一個(gè)方法異常，正如這個(gè)錯(cuò)誤調(diào)用 exc_info=True 。

這些是如何使用記錄器模塊的基礎(chǔ)，但是有些通常被認(rèn)為是不良操作的做法同樣值得說(shuō)明。

過(guò)度格式化字符串

應(yīng)該盡量避免使用 loggger.info(“string template {}”.format(argument)) ，可能的話(huà)盡量使用 logger.info(“string template %s”, argument)。 這是個(gè)更好的實(shí)踐，因?yàn)橹挥挟?dāng)日志被發(fā)送時(shí)，字符串才會(huì)發(fā)生真正改變。當(dāng)我們記錄的層級(jí)在 INFO 之上時(shí)，不這么做會(huì)導(dǎo)致浪費(fèi)周期，因?yàn)檫@個(gè)改變?nèi)匀粫?huì)發(fā)生。

捕捉和格式化異常

通常，我們想記錄在抓取模塊異常的日志信息，如果這樣寫(xiě)會(huì)很直觀：

try:

    ...

except Exception as error:

    logger.info('Something bad happened: %s', error)

但是這樣的代碼會(huì)給我們顯示類(lèi)似于 Something bad happened: “secret_key.” 的日志行，這并不是很有用。如果我們使用 exc_info 作為事先說(shuō)明，那么它將會(huì)如下顯示：

try:

    ...

except Exception:

    logger.info('Something bad happened', exc_info=True)

Something bad happened

Traceback (most recent call last):

  File 'sample_project.py', line 10, in code

    inner_code()

  File 'sample_project.py', line 6, in inner_code

    x = data['secret_key']

KeyError: 'secret_key'

這不僅僅會(huì)包含異常的準(zhǔn)確資源，同時(shí)也會(huì)包含它的類(lèi)型。

設(shè)置記錄器

裝備我們的軟件很簡(jiǎn)單，我們需要設(shè)置日志棧，并且制定這些記錄是如何被發(fā)出的。

以下是設(shè)置日志棧的多種方法

基礎(chǔ)設(shè)置

這是至今最簡(jiǎn)單的設(shè)置日志記錄的方法。使用 logging.basicConfig(level=”INFO”) 搭建一個(gè)基礎(chǔ)的 StreamHandler ，這樣就會(huì)記錄在 INFO 上的任何東西，并且到控制臺(tái)以上的級(jí)別。以下是編寫(xiě)基礎(chǔ)設(shè)置的一些參數(shù)：

在設(shè)置簡(jiǎn)單的腳本上，這是簡(jiǎn)單又使用的方法。

請(qǐng)注意， basicConfig 僅僅在運(yùn)行的一開(kāi)始可以這么調(diào)用。如果你已經(jīng)設(shè)置了你的根記錄器，調(diào)用 basicConfig 將不會(huì)奏效。

字典設(shè)置

所有元素的設(shè)置以及如何連接它們可以作為字典來(lái)說(shuō)明。這個(gè)字典應(yīng)當(dāng)由不同的部分組成，包括記錄器、處理器、格式化以及一些基本的通用參數(shù)。

例子如下：

config = {

    'disable_existing_loggers': False,

    'version': 1,

    'formatters': {

        'short': {

            'format': '%(asctime)s %(levelname)s %(name)s: %(message)s'

        },

    },

    'handlers': {

        'console': {

            'level': 'INFO',

            'formatter': 'short',

            'class': 'logging.StreamHandler',

        },

    },

    'loggers': {

        '': {

            'handlers': ['console'],

            'level': 'ERROR',

        },

        'plugins': {

            'handlers': ['console'],

            'level': 'INFO',

            'propagate': False

        }

    },

}

import logging.config

logging.config.dictConfig(config)

當(dāng)被引用時(shí)， dictConfig 將會(huì)禁用所有運(yùn)行的記錄器，除非 disable_existing_loggers 被設(shè)置為 false。這通常是需要的，因?yàn)楹芏嗄K聲明了一個(gè)全球記錄器，它在 dictConfig 被調(diào)用之前被導(dǎo)入的時(shí)候?qū)?huì)實(shí)例化。

你可以查看 schema that can be used for the dictConfig method（鏈接）。通常，這些設(shè)置將會(huì)存儲(chǔ)在一個(gè) YAML 文件中，并且從那里設(shè)置。很多開(kāi)發(fā)者會(huì)傾向于使用這種方式而不是使用 fileConfig（鏈接）,因?yàn)樗鼮槎ㄖ苹峁┝烁玫闹С帧?/p>

拓展 logging

幸虧設(shè)計(jì)了這種方式，拓展 logging 模塊很容易。讓我們來(lái)看些例子：

logging JSON | 記錄 JSON

只要我們想要記錄，我們可以通過(guò)創(chuàng)建一種自定義格式化來(lái)記錄 JSON ，它會(huì)將日志記錄轉(zhuǎn)化為 JSON 編碼的字符串。

import logging

import logging.config

import json

ATTR_TO_JSON = ['created', 'filename', 'funcName', 'levelname', 'lineno', 'module', 'msecs', 'msg', 'name', 'pathname', 'process', 'processName', 'relativeCreated', 'thread', 'threadName']

class JsonFormatter:

    def format(self, record):

        obj = {attr: getattr(record, attr)

                  for attr in ATTR_TO_JSON}

        return json.dumps(obj, indent=4)

 

handler = logging.StreamHandler()

handler.formatter = JsonFormatter()

logger = logging.getLogger(__name__)

logger.addHandler(handler)

logger.error('Hello')

添加更多上下文

在格式化中，我們可以指定任何日志記錄的屬性。

我們可以通過(guò)多種方式增加屬性，在這個(gè)例子中，我們用過(guò)濾器來(lái)豐富日志記錄。

import logging

import logging.config

GLOBAL_STUFF = 1

 

class ContextFilter(logging.Filter):

    def filter(self, record):

        global GLOBAL_STUFF

        GLOBAL_STUFF += 1

        record.global_data = GLOBAL_STUFF

        return True

 

handler = logging.StreamHandler()

handler.formatter = logging.Formatter('%(global_data)s %(message)s')

handler.addFilter(ContextFilter())

logger = logging.getLogger(__name__)

logger.addHandler(handler)

 

logger.error('Hi1')

logger.error('Hi2')

這樣有效地在所有日志記錄中增加了一個(gè)屬性，它可以通過(guò)記錄器。格式化會(huì)在日志行中包含這個(gè)屬性。

請(qǐng)注意這會(huì)在你的應(yīng)用中影響所有的日志記錄，包含你可能用到以及你發(fā)送日志的庫(kù)和其他的框架。它可以用來(lái)記錄類(lèi)似于在所有日志行里的一個(gè)獨(dú)立請(qǐng)求 ID ，去追蹤請(qǐng)求或者去添加額外的上下文信息。

從 Python 3.2 開(kāi)始，你可以使用 setLogRecordFactory 去獲得所有日志的創(chuàng)建記錄和增加額外的信息。這個(gè) extra attribute 和 LoggerAdapter class 或許同樣是有趣的。

緩沖日志

有時(shí)候當(dāng)錯(cuò)誤發(fā)生時(shí)，我們想要排除日志故障。創(chuàng)建一個(gè)緩沖的處理器，來(lái)記錄當(dāng)錯(cuò)誤發(fā)生時(shí)的最新故障信息是一種可行的辦法。下面的代碼是個(gè)非人為策劃的例子：

import logging

import logging.handlers

 

class SmartBufferHandler(logging.handlers.MemoryHandler):

    def __init__(self, num_buffered, *args, **kwargs):

        kwargs['capacity'] = num_buffered + 2  # +2 one for current, one for prepop

        super().__init__(*args, **kwargs)

 

    def emit(self, record):

        if len(self.buffer) == self.capacity - 1:

            self.buffer.pop(0)

        super().emit(record)

 

handler = SmartBufferHandler(num_buffered=2, target=logging.StreamHandler(), flushLevel=logging.ERROR)

logger = logging.getLogger(__name__)

logger.setLevel('DEBUG')

logger.addHandler(handler)

 

logger.error('Hello1')

logger.debug('Hello2')  # This line won't be logged

logger.debug('Hello3')

logger.debug('Hello4')

logger.error('Hello5')  # As error will flush the buffered logs, the two last debugs will be logged

更多信息

這篇關(guān)于日志記錄庫(kù)的靈活性和可配置性的介紹，目的在于證明它如何設(shè)計(jì)了分別的關(guān)注點(diǎn)的美學(xué)。它同樣為任何對(duì) logging documentation 和 how-to guide 感興趣的人提供了一個(gè)堅(jiān)實(shí)的基礎(chǔ)。雖然這篇文章對(duì)于 Python 日志模塊并不是一個(gè)綜合性的知道，但是這里有一些針對(duì)于常見(jiàn)的問(wèn)題的回答。

問(wèn)：我的庫(kù)發(fā)送了一個(gè)“ no logger configured” 的警告

答：從 The Hitchhiker’s Guide to Python 查閱 how to configure logging in a library

問(wèn)：如果一個(gè)記錄器沒(méi)有層級(jí)設(shè)置會(huì)怎么樣？

答：記錄器的有效層級(jí)，會(huì)由它的父級(jí)遞歸定義。

問(wèn)：我所有的日志都在本地時(shí)間，我如何記錄在 UTC ？

答：格式化就是答案！你需要在你的格式化中設(shè)置 converter 屬性為通用的 UTC 時(shí)間。使用 converter = time.gmtime 。

看完本文有收獲？請(qǐng)轉(zhuǎn)發(fā)分享給更多人

關(guān)注「Python開(kāi)發(fā)者」，提升Python技能