日誌的藝術 | 好文推薦

後臺回復【入門資料】

送你十本Python電子書

最近看到的一篇好文，推薦大家收藏閱讀。與前幾天推薦的 loguru 庫的文章，可以對照學習。

相關文章：

Python 中更優雅的日誌記錄方案

Logbook：Python 快速日誌記錄實踐

文 | xybaby推薦 | 編程派公眾號微信號：codingpy

程式設計師學習每一門語言都是從列印「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是日誌的主體內容，應該簡明扼要的描述發生的什麼事情。要求可以通過日誌本身，而不是重新閱讀產生日誌的代碼，來大致搞清楚發生了什麼事情。所以，下面這個日誌是不合格的：

1 def user_login(username, password):

2 if not valid_username(username):

3 logger.warn('Error Happened')

4 return

5 # some others code

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

1 def user_login(username, password):

2 if not valid_username(username):

3 logger.warn('user_login failed due to unvalid_username')

4 return

5 # some others code

who：the uniq identify

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

1 def user_login(username, password):

2 # some code has check the username

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

4 logger.warn('user_login failed due to password')

5 return

6 # 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專指高度依賴於具體的日誌內容的信息，這些信息，是用於定位問題的具體原因。比如

1 def user_login(username, password):

2 # some code has check the username

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

4 logger.warn('user_login failed due to password, username %s', username)

5 return

6 # some others code

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

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

how to log and tipsuse 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。尤其是在異步，並發的情況下，程式設計師任務的不可能都會成為可能。

比如下面的偽代碼

1 def magic_func():

2 if check_ok():

3 do_something()

4

5 return

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

lazy logging

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

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

1 #coding=utf-8

2 import logging

3

4 logger = logging.getLogger('LazyLogging')

5 logger.setLevel(logging.DEBUG)

6 hander = logging.StreamHandler()

7 formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

8 hander.setFormatter(formatter)

9 logger.addHandler(hander)

10

11 def getUserCount():

12 logger.info('getUserCount is called')

13 return 1

14

15 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 called2017-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上的這篇文章，也是可以解決第二個問題的，方案如下

1 class lazyEval:

2 def __init__(self, f, *args):

3 self.func = f

4 self.args = args

5

6 def __str__(self):

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

8

9 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！

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

references

Distributed systems for fun and profit

python logging#logrecord-attributes

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

原文：https://www.cnblogs.com/xybaby/p/7954610.html

回復下方「關鍵詞」，獲取優質資源

回復關鍵詞「 pybook03」，立即獲取主頁君與小夥伴一起翻譯的《Think Python 2e》電子版

回復關鍵詞「入門資料」，立即獲取主頁君整理的 10 本 Python 入門書的電子版

回復關鍵詞「m」，立即獲取Python精選優質文章合集

回復關鍵詞「book 數字」，將數字替換成 0 及以上數字，有驚喜好禮哦~

推薦閱讀

題圖：pexels，CC0 授權。