程序員學習每一門語言都是從打印“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， 而是泛指將日志內容輸出到任何目標，包括但不限於終端、文件、網絡傳輸。
本文地址：http://www.cnblogs.com/xybaby/p/7954610.html
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 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 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 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 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