程式設計師學習每一門語言都是從列印“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 2 3 4 5 |
def user_login(username, password): if not valid_username(username): logger.warn('Error Happened') return # some others code |
是的，我知道，出了問題了，但是日誌應該告訴我出了什麼問題，所以日誌至少應該是這樣的：
|
1 2 3 4 5 |
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），用於區分同樣的事件。特別是在伺服器端，都是大量使用者、請求的併發，如果日誌內容不包含唯一標識資訊，那麼這條日誌就會淹沒在茫茫大海中，比如下面這條日誌：
|
1 2 3 4 5 6 |
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 |
上面的程式碼給出了出了什麼問題，但是沒有包含是誰出了問題，至少應該是
|
1 2 3 4 5 |
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 2 3 4 5 6 |
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。尤其是在非同步，併發的情況下，程式設計師任務的不可能都會成為可能。
比如下面的虛擬碼
|
1 2 3 4 5 |
def magic_func(): if check_ok(): do_something() return |
程式碼很簡單，如果條件滿足，那麼就做相應處理，否則直接返回。這裡有兩種可能，第一種是條件不滿足是可能的、可預期的情況，只是說，在這種情況下什麼都不用作；第二種情況是程式設計師覺得條件一定會滿足，一定不會出現else的情況，所以什麼都沒做。如果是第二種情況，那麼就一定得加日誌，因為一切都可能發生。
lazy logging
日誌的內容，在最終輸出的時候，應該是一個字串，那麼這個字串是什麼時候產生呢？前面提到，我們可以通過log level來控制一條日誌是否被輸出，那麼字串的生成越遲越好，因為有可能日誌根本就無需輸出，也就無需生成這個字串，這也是我之前提到過的lazy思想。
至於lazy logging，各個語言、框架都是大同小異的，在這篇文章中，舉出了log4j的例子，在這裡還是用我比較熟悉的python講解這個例子
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
#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上的這篇文章，也是可以解決第二個問題的，方案如下
|
1 2 3 4 5 6 7 8 9 |
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！
從今天起，寫好每一條日誌吧，與君共勉！