歡迎光臨
每天分享高質量文章

日誌的藝術

來自: xybaby 

www.cnblogs.com/xybaby/p/7954610.html

程式員學習每一門語言都是從打印“hello world”開始的,日誌也是新手程式員學習、除錯程式的一大利器。當專案上線之後,也會有各種各樣的日誌,比如記錄用戶的行為、服務器的狀態、異常情況等等。打印日誌似乎是一件很簡單、不值得一提的事情。但是,當看到線上專案居然有這樣的日誌的時候,不禁想問問我們真的會打印日誌嗎?

***********************************

Error Happened, F*ck

User xxx can not login

在我看來,打印日誌是一門藝術,而且長期被程式員所忽視,本文嘗試回答以下幾個問題,分享我對打印日誌的一些思考:

(1) why or when to log

(2) what to log

(3) how to log and tips

註意:本文中會用“打印”日誌來統一表示日誌的輸出,但不是我們狹義理解的輸出到終端或者stdout、stderr, 而是泛指將日誌內容輸出到任何標的,包括但不限於終端、檔案、網絡傳輸。

why or when to log

為什麼時候要打印日誌,或者什麼時候打印日誌,在我看來是同一個問題,那就是打印日誌的目的。不同的目的,決定了日誌內容的格式,輸出的頻度,輸出的目的地。那可能有哪些打印日誌的原因?

(1)除錯開發

目的是開發期除錯程式使用,這種日誌量比較大,且沒有什麼實質性的意義,只應該出現在開發期,而不應該在專案上線之後輸出。如何控制這種型別的日誌是否輸出,後面也會詳細討論。

(2)用戶行為日誌

這種型別的日誌,記錄用戶的操作行為,用於大資料分析,比如監控、風控、推薦等等。這種日誌,一般是給其他團隊分析使用,而且可能是多個團隊,因此一般會有一定的格式要求,開發者應該按照這個格式來記錄,便於其他團隊的使用。當然,要記錄哪些行為、操作,一般也是約定好的,因此,開發者主要是執行的角色。

(3)程式運行日誌

記錄程式的運行狀況,特別是非預期的行為、異常情況,這種日誌,主要是給開發、維護人員使用。什麼時候記錄,記錄什麼內容,完全取決於開發人員,開發者具有高度自主性。本文討論的主要也是指這種型別的日誌,因為作為一個服務端開發、運維人員,程式運行日誌往往是解決線上問題的救命稻草。

(4)記錄系統或者機器的狀態

比如網絡請求、系統CPU、記憶體、IO使用情況等等,這種日誌主要是給運維人員使用,生成各種更直觀的展現形式,在系統出問題的時候報警。

what to log

一條日誌要包含哪些內容,我覺的應該包含 when、where、how、what、who、context,具體含義會在下麵一個小節介紹。

我們要記錄日誌,總是要在某個時機,比如用戶的某個請求、某個網絡呼叫、或者內部狀態發生了改變。在後文中,統稱為事件(event),即日誌內容是對某個事件的描述。

when: the time event happens

when,就是我們打印日誌的時間(時間戳),註意這裡的時間指的是日誌記錄的事件的發生時間,而不是日誌被最終輸出的時間。比如如果日誌的輸出標的是檔案,那麼這裡的when不是寫入到檔案的時間,因為往往有延遲。

時間的重要性,在《Distributed systems for fun and profit》中有很好的講述。

首先,時間可以被解讀(Interpretaion)成具體的、現實的日期,讓我們可以知道事件發生時的時間環境,比如出問題的時候是不是有什麼活動、結合系統日誌分析當時服務器的網絡、CPU、IO是怎麼樣。具體的時間點也可以幫助我們分析事件的發生是不是存在某種規律,比如是不是每天、每周、每月的固定時間點都會出問題。

其次,時間可以表示一個(一組)事件的持續時間(duration)。比如,可以監控處一段代碼的執行時間,也可以記錄一個網絡請求的耗時。這個時間差也能給出我們很多信息,比如根據經驗預判當時程式的運行狀態,是否比較‘卡’。

最後,時間代表了事件發生的順序(order),我們將多個日誌按照時間排序,這個順序能幫助我們debug到底問題是怎麼產生的,是按照什麼樣的時序。這對於多行程(多執行緒)、異步、分佈式程式而言非常重要。雖然我們知道在分佈式系統維護全域性的時間(global clock)是很複雜的一件事情,但我們使用NTP協議,基本上能解決大部分的問題。

where: where the event happens

where,就是指日誌是在哪裡的被記錄的,本質上來說,是事件的產生地點。根據情況,可以具體到是哪個模塊、哪個檔案,甚至是哪一個函式、哪一行代碼。實踐告知,至少應該包含模塊信息。

where的意義在於能夠讓自己或者其他程式員一眼就看出這條日誌是在哪裡產生的,這樣就能大致定位問題處在哪裡,而不用從日誌內容全域性grep代碼

how:how importance of the event

how important,代表了事件的重要性,我們會打印很多各種型別的日誌,但是不同的日誌的重要性是不一樣的。比如,除錯日誌是最不重要的,是不應該出現在線上專案的,但是程式運行報錯日誌卻需要認真對待,因為代表程式已經出現了異常。即使是程式的報錯日誌,也有不同的緊急程度,一次網絡請求超時跟子行程異常退出份量完全不一樣。

因此,每一條日誌都應該有log level,log level代表了日誌的重要性、緊急程度。不同的語言、框架的level細分有一定的差異,但都會包括debug,info,warn,error,fatal(critical)。其重要程度從名字就可以看出。

當然,有時候,warn與error,或者error與fatal之間的界限不那麼明顯,這個需要在團隊之間達成共識。在我們的線上專案,對於error、fatal級別的日誌都會報警,如果出現了error日誌,那麼最遲需要第二天去處理,如果是fatal日誌,即使是在大半夜,也得立刻起來分析、處理。

what:what is the log message

what是日誌的主體內容,應該簡明扼要的描述發生的什麼事情。要求可以通過日誌本身,而不是重新閱讀產生日誌的代碼,來大致搞清楚發生了什麼事情。所以,下麵這個日誌是不合格的:

def user_login(username, password):

    if not valid_username(username):

        logger.warn(‘Error Happened’)

        return

    # some others code

是的,我知道,出了問題了,但是日誌應該告訴我出了什麼問題,所以日誌至少應該是這樣的:


def user_login(username, password):

    if not valid_username(username):

        logger.warn(‘user_login failed due to unvalid_username’)

        return

    # some others code


who:the uniq identify

who代表了事件產生者的唯一標識(identity),用於區分同樣的事件。特別是在服務器端,都是大量用戶、請求的併發,如果日誌內容不包含唯一標識信息,那麼這條日誌就會淹沒在茫茫大海中,比如下麵這條日誌:

def user_login(username, password):

    # some code has check the username

    if not valid_password(password) or not check_password(username, password):

        logger.warn(‘user_login failed due to password’)

        return

    # some others code

上面的代碼給出了出了什麼問題,但是沒有包含是誰出了問題,至少應該是

def user_login(username, password):

    # some code has check the username

    if not valid_password(password) or not check_password(username, password):

        logger.warn(‘user_login failed due to password, username %s’, username)

        return


日誌的唯一標識也能幫助我們檢索、過濾,找出該唯一標識的最近一段時間的所有日誌,再按照時間排序,就能還原日誌主體的活動軌跡,比如一個用戶在網站上的操作會發散到多個行程、服務。當通過用戶名(用戶的唯一標識)搜索日誌時,就能還原該玩家的操作記錄,這個在查線上問題的時候非常有效。

當然,這個唯一標識是很廣泛的,需要根據具體情況決定,如果網絡請求,可能更好的是requestid、sessionid;如果是系統日誌,那麼可能是行程、執行緒ID;如果是分佈式集群,那麼可能是副本的唯一id

context: environment when event happens

日誌記錄的事件發生的背景關係環境直觀重要,能告知事件是在什麼樣的情況發生的。當然,上面提到的when、where、who都屬於背景關係,這些都是固定的,通用的。而在本小節,context專指高度依賴於具體的日誌內容的信息,這些信息,是用於定位問題的具體原因。比如

def user_login(username, password):

    # some code has check the username

    if not valid_password(password) or not check_password(username, password):

        logger.warn(‘user_login failed due to password, username %s’, username)

        return

    # some others code

閱讀代碼,當password不符合規範,或者校驗password失敗的時候都會出錯,但是到底是那種情況呢,日誌內容並沒有指出,所以這條日誌仍然不合格。

在我看來,這部分是彈性最大,但是又最重要的部分,造成異常的情況很多,記錄哪些信息,完全取決於寫代碼的程式員。但事實上也很簡單,遵循一個原則即可:想想加上哪些信息能定位問題發生的原因

how to log and tips

use logging framework

早期的編程語言提供的日誌功能都比較初級,一般都是輸出到終端或者檔案,如C++、Java,而且不支持統一的輸出格式的配置。對於這些語言,一般會有單獨的log框架,如glog,log4cpp,log4j,elf4j等等。而更新的一些語言,一般都內置強大的logging模塊,如python。

在前面在講述“what to log”的時候,我們指出要記錄日誌發生的時間、地點、等級等信息。那麼這些信息是不是每次都在日誌內容裡面打印呢,這些內容確實是一條完整的日誌所必須的,但是如果要程式員寫每條日誌的時候都得手動加上這些內容,那麼無疑是一種負擔。框架、模塊的作用就是將程式員從這些繁文縟節中解放出來。比如在很多logging框架模塊(thon logging、log4j)中,都有named logger這一概念,這個name就可以是module, filename, classname或者instance,這就解決了上一章節提到了“where the event happen”這個問題。

在這裡,對logging框架的介紹就不詳細展開,只是總結一下logging框架、模塊的功能

(1)設置log的輸出等級

這樣可以不改程式代碼,僅僅修改log的輸出等級,就能夠控制哪些日誌輸出,哪些日誌不輸出。比如我們在開發期的除錯日誌,都可以設置為DEBUG,上線的時候設置輸出等級為INFO,那麼這些除錯日誌就不會被輸出。

(2)設置每條日誌預設包含的內容

以Python logging為例,可以通過formatter設置每條日誌預設包含哪些信息,比如時間、檔案、行號、行程、執行緒信息。

(3)設置日誌的輸出標的

通過配置,可以指定日誌是輸出到stdout,還是檔案,還是網絡。特別是在linux服務器上,將日誌輸出到syslog,再使用syslog強大的處理、分發功能,配合elk系統進行分析,是很多應用程式的通用做法。

log never throw

我們打印日誌,是為了記錄事故發生的現場,以便發現問題,解決問題。那麼就得保證,打印日誌這一行為本身不能引入新的問題,比如,不能出錯拋異常。這就好比,處理車禍的消防車不能衝進現場一樣。

但是,越重要的日誌,比如Error、 Fatal級別的日誌,出現的概率應該是越低的,我們也不希望產生這樣的日誌,因為一旦出現就意味著異常或者線上事故。這樣的日誌,就一定要做好單元測試、改寫率測試,保證日誌本身是能夠正常工作的。

log when u think something never happen

這一點,應該是針對why or when to log而言。就是說,當你認為某種情況一定不會發生,按照墨菲定律,它還是很可能會發生,那麼就應該在萬一發生的情況記錄log,Error(Fatal)級別的log。尤其是在異步,併發的情況下,程式員任務的不可能都會成為可能。

比如下麵的偽代碼

def magic_func():

    if check_ok():

        do_something()

 

    return

代碼很簡單,如果條件滿足,那麼就做相應處理,否則直接傳回。這裡有兩種可能,第一種是條件不滿足是可能的、可預期的情況,只是說,在這種情況下什麼都不用作;第二種情況是程式員覺得條件一定會滿足,一定不會出現else的情況,所以什麼都沒做。如果是第二種情況,那麼就一定得加日誌,因為一切都可能發生。

lazy logging

日誌的內容,在最終輸出的時候,應該是一個字串,那麼這個字串是什麼時候產生呢?前面提到,我們可以通過log level來控制一條日誌是否被輸出,那麼字串的生成越遲越好,因為有可能日誌根本就無需輸出,也就無需生成這個字串,這也是我之前提到過的lazy思想。

至於lazy logging,各個語言、框架都是大同小異的,在這篇文章中,舉出了log4j的例子,在這裡還是用我比較熟悉的python講解這個例子

#coding=utf-8

import logging

logger = logging.getLogger(‘LazyLogging’)

logger.setLevel(logging.DEBUG)

hander = logging.StreamHandler()

formatter = logging.Formatter(‘%(asctime)s – %(name)s – %(levelname)s – %(message)s’)

hander.setFormatter(formatter)  

logger.addHandler(hander)

 

def getUserCount():

    logger.info(‘getUserCount is called’)

    return 1

 

logger.debug(“There are “ + str(getUserCount()) + ” users logged in now.”)

上面的代碼可謂麻雀雖小五臟俱全,包含了使用logging框架的方方面面。第4行是named logger,第5行設置log level,第6行指定輸出標的,第7行指定輸出格式(包括時間,logger name,log level,具體的日誌內容)。

運行結果如下:

2017-12-02 17:52:20,049 – LazyLogging – DEBUG – getUserCount is called
2017-12-02 17:52:20,049 – LazyLogging – INFO – There are 1 users logged in now.

由於當前的log level是DEBUG,那麼第15行的日誌會輸出,這是正常的。

但是將log level改成INFO,“getUserCount is called”這條日誌仍然會被輸出。這就暴露出兩個問題,第一,即使日誌內容最終不會被輸出,仍然會生成一個字串;第二,一定會呼叫getUserCount 這個函式,而如果根據log lebel不需要輸出日誌,這兩步都是沒有必要的

要解決第一個問題很簡單,將第15行改成

logger.debug(“There are %s users logged in now.”, getUserCount())

即可,但是“getUserCount is called”這條日誌仍然會被輸出,即第二個問題仍然沒有解決

按照stackoverflow上的這篇文章,也是可以解決第二個問題的,方案如下

class lazyEval:

    def __init__(self, f, *args):

        self.func = f

        self.args = args

 

    def __str__(self):

        return str(self.func(*self.args))

 

logger.debug(“There are %s users logged in now.”, lazyEval(getUserCount))

在log lever為INFO的時候,可以發現“getUserCount is called”也不會被輸出了,即不會呼叫getUserCount函式,做到了真正的lazy logging。

但是,這是非常不好的寫法!除非你們保證所呼叫的函式是沒有副作用的(side-effect),即函式的呼叫無狀態,不會改變程式的狀態,否則程式的狀態居然會依賴於log level,這是一個陷阱,一個坑,一點都不pythonic。

consider async logging

日誌的記錄也是要消耗時間的,這也是我們不能到處打印日誌的原因。一般來說,logging框架的效率都是比較高的,但是如果profile發現日誌的輸出確實帶來了不容忽視的消耗,那麼也是值得優化的,其中的一個方法就是異步log,以避免日誌輸出阻塞執行緒

conclusion

在網上看到這麼一句話

Logs are like car insurance. Nobody wants to pay for it, but when something goes wrong everyone wants the best available

log就像車輛保險,沒人願意為保險付錢,但是一旦出了問題誰都又想有保險可用。

我們打印日誌的時候都很隨意,於是在差bug的時候,就會罵別人、或者幾天前的自己:SB!

從今天起,寫好每一條日誌吧,與君共勉!

參考

  • Distributed systems for fun and profit

  • python logging#logrecord-attributes

  • the-art-of-logging-advanced-message-formatting


●本文編號333,以後想閱讀這篇文章直接輸入333即可

●輸入m獲取到文章目錄

推薦↓↓↓

 

Web開發

更多推薦18個技術類公眾微信

涵蓋:程式人生、演算法與資料結構、黑客技術與網絡安全、大資料技術、前端開發、Java、Python、Web開發、安卓開發、iOS開發、C/C++、.NET、Linux、資料庫、運維等。

赞(0)

分享創造快樂