我們?cè)陂_發(fā)基于Flask的Web應(yīng)用時(shí)，往往容易忽略了對(duì)日志的使用，而在Flask的官方文檔中，對(duì)日志這塊的介紹也僅僅停留在如何與系統(tǒng)集成上。記錄日志這個(gè)看似很簡單的事情，在實(shí)際中很多人卻不一定能做好，要么不知道何時(shí)進(jìn)行日志記錄，要么就是記錄的日志然并卵。所以，今天就來說說記錄日志這件小事。

說它是件小事，因?yàn)樗拇_不會(huì)影響你系統(tǒng)的正常流程，有沒有它系統(tǒng)都能跑起來，也正因?yàn)檫@樣，很多人便忽略了日志的處理，或者干脆都沒有配置日志輸出，整個(gè)系統(tǒng)沒有任何日志輸出（Nginx日志不算）。當(dāng)然，如果是我們自己開發(fā)的一些小網(wǎng)站，大家用來練練手或著用戶量不大，有沒有日志都一樣，但是對(duì)于一些大型的系統(tǒng)，它的用戶是很多的，在任何一個(gè)環(huán)節(jié)都可能出問題，為了能夠及時(shí)的定位問題和監(jiān)控系統(tǒng)運(yùn)行狀態(tài)，正確合理的記錄日志就非常非常重要了。一般情況下，我們需要關(guān)注的是三個(gè)方面的內(nèi)容：

• 日志信息的集中采集、存儲(chǔ)和檢索：這個(gè)主要是在多節(jié)點(diǎn)的情況下如何方便的查看日志信息。

• 日志信息的輸出策略：要保證日志輸出的全面而又不顯凌亂，方便開發(fā)人員跟蹤和分析問題。

• 關(guān)鍵業(yè)務(wù)的日志輸出：我們常說的打點(diǎn)就屬于這個(gè)范疇，比如我們的一些瀏覽記錄等，這個(gè)就需要根據(jù)業(yè)務(wù)要求來做針對(duì)性設(shè)計(jì)了。

我們?cè)谶@里主要是圍繞第二個(gè)問題來展開，也是我們開發(fā)人員最直接接觸的情況。

日志輸出級(jí)別

從Flask 0.3 版本開始，系統(tǒng)就已經(jīng)幫我們預(yù)配置了一個(gè)logger，而這個(gè)logger的使用也是非常簡單：

app.logger.debug('A value for debugging')
app.logger.warning('A warning occurred (%d apples)', 42)
app.logger.error('An error occurred')

其中的app就是Flask的實(shí)例，而這個(gè)app.logger也就是一個(gè)標(biāo)準(zhǔn)的logging Logger，因此，我們?cè)谑褂胊pp.logger時(shí)可選擇的輸出級(jí)別與python logging中的定義是一致的。

• ERROR：這個(gè)級(jí)別的日志意味著系統(tǒng)中發(fā)生了非常嚴(yán)重的問題，必須有人馬上處理，比如數(shù)據(jù)庫不可用了，系統(tǒng)的關(guān)鍵業(yè)務(wù)流程走不下去了等等。很多人在實(shí)際開發(fā)的時(shí)候，不會(huì)去區(qū)分問題的重要程度，只要有問題就error記錄下來，其實(shí)這樣是非常不負(fù)責(zé)任的，因?yàn)閷?duì)于成熟的系統(tǒng)，都會(huì)有一套完整的報(bào)錯(cuò)機(jī)制，那這個(gè)錯(cuò)誤信息什么時(shí)候需要發(fā)出來，很多都是依據(jù)單位時(shí)間內(nèi)error日志的數(shù)量來確定的。因此如果我們不分輕重緩急，一律error對(duì)待，就會(huì)徒增報(bào)錯(cuò)的頻率，久而久之，我們的救火隊(duì)員對(duì)錯(cuò)誤警報(bào)就不會(huì)那么在意，這個(gè)警報(bào)也就失去了原始的意義。

• WARN：發(fā)生這個(gè)級(jí)別的問題時(shí)，處理過程可以繼續(xù)，但必須要對(duì)這個(gè)問題給予額外的關(guān)注。假設(shè)我們現(xiàn)在有一個(gè)系統(tǒng)，希望用戶每一個(gè)月更換一次密碼，而到期后，如果用戶沒有更新密碼我們還要讓用戶可以繼續(xù)登錄，這種情況下，我們?cè)谟涗浫罩緯r(shí)就需要使用WARN級(jí)別了，也就是允許這種情況存在，但必須及時(shí)做跟蹤檢查。

• INFO：這個(gè)級(jí)別的日志我們用的也是比較多，它一般的使用場景是重要的業(yè)務(wù)處理已經(jīng)結(jié)束，我們通過這些INFO級(jí)別的日志信息，可以很快的了解應(yīng)用正在做什么。我們以在12306上買火車票為例，對(duì)每一張票對(duì)應(yīng)一個(gè)INFO信息描述“[who] booked ticket from [where] to [where]”。

• DEBUG和TRACE：我們把這兩個(gè)級(jí)別放在一起說，是應(yīng)為這兩個(gè)級(jí)別的日志是只限于開發(fā)人員使用的，用來在開發(fā)過程中進(jìn)行調(diào)試，但是其實(shí)我們有時(shí)候很難將DEBUG和TRACE區(qū)分開來，一般情況下，我們使用DEBUG足以。

以上就是我們實(shí)際開發(fā)中最多接觸的幾種日志級(jí)別，基本能覆蓋99%的情況。最后我們要注意的就是，最好能盡可能輸出更多的日志信息，并且不做任何過濾，同時(shí)輸出的每一條日志的詳細(xì)信息要切當(dāng)，讓我們可以快速過濾并找到所需的信息。

日志輸出信息

當(dāng)我們確定了使用哪個(gè)級(jí)別來寫入日志后，下一步要做的就是確定要記錄什么樣的信息。針對(duì)這一塊的內(nèi)容，其實(shí)又可以細(xì)分。

日志應(yīng)該記錄什么

一般來說，日志的記錄要滿足幾個(gè)要求：可讀、干凈、詳細(xì)和自描述。我們先來看幾個(gè)反模式的例子：

app.logger.debug('message processed')
app.logger.debug(message.get_message_id())
app.logger.debug('message with id %s', message.get_message_id())

if isinstance(message, TextMessage):
    ...else:
    app.logger.warn('unknow message type')

上面列出的這幾個(gè)例子，問題在什么地方呢？當(dāng)看到這些日志信息后，我們首先意識(shí)到的肯定是哪里出了問題，但是，這個(gè)問題產(chǎn)生的原因是什么我們并不清楚，也就是說，只根據(jù)這樣的日志我們是沒辦法對(duì)問題進(jìn)行修復(fù)的。所以我們?cè)谟涗浫罩镜臅r(shí)候，應(yīng)該要盡量的詳細(xì)，日志的上下文要交代清楚。

另外一種反模式的日志信息，我們通常叫做魔法日志。就比如說，有的開發(fā)人員為了自己查找信息方便，會(huì)輸出一些類似&&&###>>>>>>的日志，這些特殊的符號(hào)只有開發(fā)者本人清楚到底是做什么的，而對(duì)其他人來說，看到這些日志絕對(duì)是一臉懵逼。即使是開發(fā)者本人，哪怕當(dāng)時(shí)能夠清楚這些魔法日志的特殊含義，但時(shí)間一長，估計(jì)他們也很難回想起當(dāng)時(shí)為啥要輸出這些鬼東西了吧。

其次，還有一種是要關(guān)注外部系統(tǒng)，也就是在和任何外部系統(tǒng)通信的時(shí)候，建議記錄所有進(jìn)出系統(tǒng)的數(shù)據(jù)。但是，記錄這些信息時(shí)，性能是一個(gè)比較頭痛的問題，有時(shí)，需要和外部系統(tǒng)交換的信息量太大，導(dǎo)致無法記錄所有信息。但是，在調(diào)試或測試期間我們還是愿意記錄所有信息，并準(zhǔn)備為此付出一些性能的代價(jià)，這個(gè)可以通過仔細(xì)控制log級(jí)別來實(shí)現(xiàn)，比如：

if app.config['debug']:
    app.logger.debug('...')else:
    app.logger.info('...')

最后要提的一點(diǎn)就是，我們輸出的這些日志信息中，絕對(duì)不可以透露系統(tǒng)密碼和一些個(gè)人信息。

如何打印日志內(nèi)容

當(dāng)我們明確了該用哪個(gè)級(jí)別去記錄哪些信息后，就要把這些信息輸出到日志文件中，但是想正確高效的打印日志內(nèi)容也并非一件簡單的事。Flask已經(jīng)幫我們預(yù)配置了一個(gè)logger，我們可以使用這個(gè)logger來完成我們所有的打印操作。

我們?cè)谟涗浫罩镜臅r(shí)候絕對(duì)不可以使用print，即使我們?cè)陂_發(fā)調(diào)試的時(shí)候能夠在控制臺(tái)看到打印的信息，但是這樣的信息并不會(huì)記錄到日志文件中，當(dāng)我們的程序上線后，跟沒有記錄日志的效果是一樣的。因此，哪怕是在開發(fā)調(diào)試時(shí)，也要盡量使用logger。

最簡單的日志打印就是輸出一個(gè)字符串，比如像下面這樣

app.logger.info('this is a string')

但大部分時(shí)候，我們要記錄的信息都會(huì)包含一些參數(shù)，有一種實(shí)現(xiàn)方式是提前構(gòu)造出這個(gè)字符串

message_info = 'the message is %s' % info
app.logger.info(message_info)

這種寫法也沒啥問題，但其實(shí)，logger內(nèi)部也可以幫助我們完成上面的操作，也就是我們還可以寫成下面這樣

app.logger.info('the message if %s', info)

這樣看起來是不是簡潔了好多呢？

記錄異常信息

記錄異常信息嚴(yán)格來說也應(yīng)該算到日志輸出的范疇，之所以把它拿出來單獨(dú)說，是因?yàn)槌苏f明應(yīng)該怎樣去記錄異常外，這里還要說下如何去自定義異常。

正確的記錄異常信息

對(duì)于異常，我們更想看到的其實(shí)是它的堆棧信息，而不是簡單的一句話，堆棧信息可以幫助我們快速的定位問題出處。如果想打印堆棧，我們前面的記錄方法就不再實(shí)用了，哪怕我們把Exception的實(shí)例丟到logger里打印出來的也僅僅是錯(cuò)誤信息而不是堆棧信息。比如下面的例子

a = [1, 2, 3]try:print a[3]
except Exception, e:
    logging.error(e)

如果我們查看日志，發(fā)現(xiàn)打印出的僅僅是一行錯(cuò)誤信息：

Tue, 24 Jan 2017 16:07:20 demo.py[line:22] ERROR list index out of range

那如何打印出堆棧信息呢？python給我們提供了一個(gè)exception方法，它的使用跟debug、info、warn、error幾個(gè)方法是一樣的，我們可以把上面的代碼修改一下

a = [1, 2, 3]try:print a[3]
except Exception, e:
    logging.exception(e)

之后我們?cè)倏慈罩据敵?/p>

Tue, 24 Jan 2017 17:19:37 demo.py[line:22] ERROR list index out of range
Traceback (most recent call last):
  File "/Users/xiaoz/developments/python/ttest/demo.py", line 20, in testprint a[3]
IndexError: list index out of range

除了我們上面使用error方法打印的錯(cuò)誤信息外，還打印出了出錯(cuò)的堆棧信息，由此看見，exception方法打印的日志會(huì)包含兩項(xiàng)，第一項(xiàng)就是調(diào)用exception方法時(shí)傳入的message，還有一項(xiàng)是緊跟在message后面的堆棧信息。

當(dāng)我們使用exception方法時(shí)，它記錄的日志級(jí)別為ERROR，如果我們希望打印出堆棧信息，同時(shí)又不希望使用ERROR這個(gè)級(jí)別怎么辦呢？如果你查看exception方法的實(shí)現(xiàn)，會(huì)發(fā)現(xiàn)，它只是多加了一行代碼kwargs['exc_info'] = 1，然后調(diào)用了error方法，以此類推，如果我們希望打印堆棧信息就可以像下面這樣寫：app.logger.info('message info is %s', message, exc_info=1)。

Flask允許我們自定義對(duì)異常的處理，一般情況下，我們會(huì)做一些統(tǒng)一處理，比如下面這樣

@app.errorhandler(500)def internal_server_error(e):app.logger.exception('error 500: %s', e)
    response = json_error('internal server error')
    response.status_code = 500return response

我們?cè)诜祷亟Y(jié)果的同時(shí)，對(duì)錯(cuò)誤信息進(jìn)行了記錄，這樣做也是為了避免模板代碼，減少開發(fā)人員的工作量。但是，在減少我們開發(fā)量的同時(shí)，這也意味著可能會(huì)帶來另外一個(gè)問題，很多程序員喜歡捕獲異常后將錯(cuò)誤寫入日志，然后再將異常包裝后重新拋出，這樣會(huì)重復(fù)打印日志信息：

... some thing ...try:
    ... do some thing ...except Exception, e:
    app.logger.error(e)raise SomeException(e)

還有一種情況，如果我們?cè)诓东@異常的時(shí)候，不分情況統(tǒng)一捕獲Exception也是不對(duì)的。直接捕獲Exception固然方便，但是我們捕獲的范圍太大的話，有的時(shí)候會(huì)吃掉關(guān)鍵的信息，而這些被吃掉的異常又沒有打印錯(cuò)誤信息和堆棧，一旦有問題，是很難排查的，比如我們定義了下面的方法

def some_method():.. do some thing ..try:
        .. do dome thing 2 ..return Trueexcept Exception, e:return False

當(dāng)do some thing 2中發(fā)生異常時(shí)，我們是沒法察覺到的，這樣不但會(huì)使方法返回不正確，也會(huì)給排查帶來困難。

自定義異常

首先，我們看看為什么要自定義異常，在需要拋出異常的地方，我們直接raise Exception()不好嗎？答案很顯然，肯定是不好，具體的原因，我們下面就逐條分析下。

1. 大多時(shí)候我們都是使用json來為不同端提供接口支持，不管成功與否，都必須使用統(tǒng)一的數(shù)據(jù)格式。如果系統(tǒng)充斥著各種異常就很難做到統(tǒng)一。

2. 要能反映出該異常的重要程度，比如：如果是參數(shù)校驗(yàn)異常則被認(rèn)為不是很重要，可能直接記下warn日志就行了，而orm異常必須要記錄error日志。

3. 最后，對(duì)于異常的信息要有區(qū)分，比如，對(duì)于orm異常，我們希望給用戶看到的是一條簡單的系統(tǒng)出錯(cuò)的提示信息，而我們?cè)诓榭慈罩緯r(shí)必須要有詳細(xì)的異常信息。

為了解決上面的問題，需要我們來自定義異常，并且使用的時(shí)候也盡量要使用已定義的異常類。這里我們來看一種實(shí)現(xiàn)方式，大家可以參考

class BaseError(Exception):default_status_code = 200LEVEL_DEBUG = 0LEVEL_INFO = 1LEVEL_WARN = 2LEVEL_ERROR = 3def __init__(self, message, status_code=None, extras=None, parent_error=None):self._message = messageself._code = status_codeself.extras = extrasself.parent_error = parent_errorself.level = BaseError.LEVEL_DEBUG

    @propertydef status_code(self):if not self._code:return BaseError.default_status_codereturn self._codedef to_dict(self):
        rv = {'error_message': self._message,'status_code': self.status_code,'success': False
        }return rvclass ValidationError(BaseError):def __init__(self, message, extras=None):super(ValidationError, self).__init__(message=message, extras=extras)self.level = BaseError.LEVEL_INFOclass NotFoundError(BaseError):def __init__(self, message, extras=None):super(NotFoundError, self).__init__(message=message, extras=extras)self.level = BaseError.LEVEL_WARNclass FormError(BaseError):def __init__(self, form):
        message = form.get_validate_error()super(FormError, self).__init__(message, extras=form.data)self.level = BaseError.LEVEL_INFOclass OrmError(BaseError):def __init__(self, message, status_code=None, extras=None, parent_error=None):super(OrmError, self).__init__(message, status_code, extras, parent_error)self.level = BaseError.LEVEL_ERROR

定義了上面的異常信息后，我們?cè)诮y(tǒng)一處理錯(cuò)誤信息的時(shí)候就可以像下面這樣實(shí)現(xiàn)：

@app.errorhandler(BaseError)def custom_error_handler(e):if e.level in [BaseError.LEVEL_WARN, BaseError.LEVEL_ERROR]:if isinstance(e, OrmError):
            app.logger.exception('%s %s' % (e.parent_error, e))else:
            app.logger.exception('錯(cuò)誤信息: %s %s' % (e.extras, e))
    response = jsonify(e.to_dict())
    response.status_code = e.status_codereturn response

如此，就兼顧了日志的錯(cuò)誤級(jí)別和接口返回的數(shù)據(jù)格式。

我們還應(yīng)該注意什么

其實(shí)，對(duì)于日志的記錄，我們前面七七八八也講了個(gè)差不多，在開發(fā)的時(shí)候如果我們能夠注意到上面提到的一些問題，已經(jīng)能夠算是比較合格的打日志了。當(dāng)然，還有一些小的問題，在最后還是要說明一下。

第一個(gè)，就是需要我們關(guān)鍵一下性能問題，也就是避免因?yàn)槿罩就下龖?yīng)用系統(tǒng)。如果輸出的日志信息太多，必然會(huì)增加磁盤的寫入負(fù)擔(dān)，通常情況下，每小時(shí)輸出到磁盤的數(shù)據(jù)量達(dá)到幾百M(fèi)就已經(jīng)是上限了。

第二個(gè)，就是不要由于log語句導(dǎo)致業(yè)務(wù)過程中斷。我們的本意是通過日志來記錄系統(tǒng)的一些運(yùn)行信息，但是，log語句本身也是有可能發(fā)生異常的，如果因?yàn)槲覀兊拇a，導(dǎo)致日志記錄的時(shí)候拋出了異常，就真的是得不償失了。

OK，關(guān)于在Flask系統(tǒng)中如何進(jìn)行日志記錄，就介紹到這了，其實(shí)，上面提到的內(nèi)容不僅在Flask系統(tǒng)中可行，基本上所有的Web系統(tǒng)都有參考價(jià)值。大家有什么問題，歡迎交流。