正文python
程序員學習每一門語言都是從打印「hello world」開始的，日誌也是新手程序員學習、調試程序的一大利器。當項目上線以後，也會有各類各樣的日誌，好比記錄用戶的行爲、服務器的狀態、異常狀況等等。打印日誌彷佛是一件很簡單、不值得一提的事情。可是，當看到線上項目竟然有這樣的日誌的時候，不由想問問咱們真的會打印日誌嗎？linux
***********************************程序員
Error Happened, F*ck編程
User xxx can not login 服務器
在我看來，打印日誌是一門藝術，並且長期被程序員所忽視，本文嘗試回答如下幾個問題，分享我對打印日誌的一些思考：網絡
(1) why or when to logsession
(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