當(dāng)我們在使用Flask時，如何記錄日志

刮骨劍 2019-06-26

展開全文

0.2 2017.01.24 18:47* 字?jǐn)?shù) 3885

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

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

日志信息的集中采集、存儲和檢索：這個主要是在多節(jié)點的情況下如何方便的查看日志信息。
日志信息的輸出策略：要保證日志輸出的全面而又不顯凌亂，方便開發(fā)人員跟蹤和分析問題。
關(guān)鍵業(yè)務(wù)的日志輸出：我們常說的打點就屬于這個范疇，比如我們的一些瀏覽記錄等，這個就需要根據(jù)業(yè)務(wù)要求來做針對性設(shè)計了。

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

日志輸出級別

從Flask 0.3 版本開始，系統(tǒng)就已經(jīng)幫我們預(yù)配置了一個logger，而這個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的實例，而這個app.logger也就是一個標(biāo)準(zhǔn)的logging Logger，因此，我們在使用app.logger時可選擇的輸出級別與python logging中的定義是一致的。

ERROR：這個級別的日志意味著系統(tǒng)中發(fā)生了非常嚴(yán)重的問題，必須有人馬上處理，比如數(shù)據(jù)庫不可用了，系統(tǒng)的關(guān)鍵業(yè)務(wù)流程走不下去了等等。很多人在實際開發(fā)的時候，不會去區(qū)分問題的重要程度，只要有問題就error記錄下來，其實這樣是非常不負(fù)責(zé)任的，因為對于成熟的系統(tǒng)，都會有一套完整的報錯機(jī)制，那這個錯誤信息什么時候需要發(fā)出來，很多都是依據(jù)單位時間內(nèi)error日志的數(shù)量來確定的。因此如果我們不分輕重緩急，一律error對待，就會徒增報錯的頻率，久而久之，我們的救火隊員對錯誤警報就不會那么在意，這個警報也就失去了原始的意義。
WARN：發(fā)生這個級別的問題時，處理過程可以繼續(xù)，但必須要對這個問題給予額外的關(guān)注。假設(shè)我們現(xiàn)在有一個系統(tǒng)，希望用戶每一個月更換一次密碼，而到期后，如果用戶沒有更新密碼我們還要讓用戶可以繼續(xù)登錄，這種情況下，我們在記錄日志時就需要使用WARN級別了，也就是允許這種情況存在，但必須及時做跟蹤檢查。
INFO：這個級別的日志我們用的也是比較多，它一般的使用場景是重要的業(yè)務(wù)處理已經(jīng)結(jié)束，我們通過這些INFO級別的日志信息，可以很快的了解應(yīng)用正在做什么。我們以在12306上買火車票為例，對每一張票對應(yīng)一個INFO信息描述“[who] booked ticket from [where] to [where]”。
DEBUG和TRACE：我們把這兩個級別放在一起說，是應(yīng)為這兩個級別的日志是只限于開發(fā)人員使用的，用來在開發(fā)過程中進(jìn)行調(diào)試，但是其實我們有時候很難將DEBUG和TRACE區(qū)分開來，一般情況下，我們使用DEBUG足以。

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

日志輸出信息

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

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

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

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')

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

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

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

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

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

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

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

我們在記錄日志的時候絕對不可以使用print，即使我們在開發(fā)調(diào)試的時候能夠在控制臺看到打印的信息，但是這樣的信息并不會記錄到日志文件中，當(dāng)我們的程序上線后，跟沒有記錄日志的效果是一樣的。因此，哪怕是在開發(fā)調(diào)試時，也要盡量使用logger。

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

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

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

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

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

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

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

記錄異常信息

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

正確的記錄異常信息

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

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

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

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

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

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

之后我們再看日志輸出

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方法打印的錯誤信息外，還打印出了出錯的堆棧信息，由此看見，exception方法打印的日志會包含兩項，第一項就是調(diào)用exception方法時傳入的message，還有一項是緊跟在message后面的堆棧信息。

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

Flask允許我們自定義對異常的處理，一般情況下，我們會做一些統(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

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

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

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

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

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

自定義異常

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

大多時候我們都是使用json來為不同端提供接口支持，不管成功與否，都必須使用統(tǒng)一的數(shù)據(jù)格式。如果系統(tǒng)充斥著各種異常就很難做到統(tǒng)一。
要能反映出該異常的重要程度，比如：如果是參數(shù)校驗異常則被認(rèn)為不是很重要，可能直接記下warn日志就行了，而orm異常必須要記錄error日志。
最后，對于異常的信息要有區(qū)分，比如，對于orm異常，我們希望給用戶看到的是一條簡單的系統(tǒng)出錯的提示信息，而我們在查看日志時必須要有詳細(xì)的異常信息。

為了解決上面的問題，需要我們來自定義異常，并且使用的時候也盡量要使用已定義的異常類。這里我們來看一種實現(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

定義了上面的異常信息后，我們在統(tǒng)一處理錯誤信息的時候就可以像下面這樣實現(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('錯誤信息: %s %s' % (e.extras, e))
    response = jsonify(e.to_dict())
    response.status_code = e.status_codereturn response

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