日志的藝術（The art of logging）

　　程式員學習每一門語言都是從列印“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 

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

　　（1）調試開發

　　目的是開發期調試程式使用，這種日志量比較大，且沒有什麼實質性的意義，隻應該出現在開發期，而不應該在項目上線之後輸出。如何控制這種類型的日志是否輸出，後面也會詳細讨論。

　　（2）使用者行為日志

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

　　（3）程式運作日志

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

　　（4）記錄系統或者機器的狀态

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

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

　　我們要記錄日志，總是要在某個時機，比如使用者的某個請求、某個網絡調用、或者内部狀态發生了改變。在後文中，統稱為事件（event），即日志内容是對某個事件的描述。

　　when，就是我們列印日志的時間（時間戳），注意這裡的時間指的是日志記錄的事件的發生時間，而不是日志被最終輸出的時間。比如如果日志的輸出目标是檔案，那麼這裡的when不是寫入到檔案的時間，因為往往有延遲。

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

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

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

　　最後，時間代表了事件發生的順序（order），我們将多個日志按照時間排序，這個順序能幫助我們debug到底問題是怎麼産生的，是按照什麼樣的時序。這對于多程序（多線程）、異步、分布式程式而言非常重要。雖然我們知道在分布式系統維護全局的時間（global clock）是很複雜的一件事情，但我們使用NTP協定，基本上能解決大部分的問題。

　　where，就是指日志是在哪裡的被記錄的，本質上來說，是事件的産生地點。根據情況，可以具體到是哪個子產品、哪個檔案，甚至是哪一個函數、哪一行代碼。實踐告知，至少應該包含子產品資訊。

　　where的意義在于能夠讓自己或者其他程式員一眼就看出這條日志是在哪裡産生的，這樣就能大緻定位問題處在哪裡，而不用從日志内容全局grep代碼

　　how important，代表了事件的重要性，我們會列印很多各種類型的日志，但是不同的日志的重要性是不一樣的。比如，調試日志是最不重要的，是不應該出現線上上項目的，但是程式運作報錯日志卻需要認真對待，因為代表程式已經出現了異常。即使是程式的報錯日志，也有不同的緊急程度，一次網絡請求逾時跟子程序異常退出份量完全不一樣。

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

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

　　 what是日志的主體内容，應該簡明扼要的描述發生的什麼事情。要求可以通過日志本身，而不是重新閱讀産生日志的代碼，來大緻搞清楚發生了什麼事情。是以，下面這個日志是不合格的：

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

　　who代表了事件産生者的唯一辨別（identity），用于區分同樣的事件。特别是在伺服器端，都是大量使用者、請求的并發，如果日志内容不包含唯一辨別資訊，那麼這條日志就會淹沒在茫茫大海中，比如下面這條日志：

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

　　日志的唯一辨別也能幫助我們檢索、過濾，找出該唯一辨別的最近一段時間的所有日志，再按照時間排序，就能還原日志主體的活動軌迹，比如一個使用者在網站上的操作會發散到多個程序、服務。當通過使用者名（使用者的唯一辨別）搜尋日志時，就能還原該玩家的操作記錄，這個在查線上問題的時候非常有效。

　　當然，這個唯一辨別是很廣泛的，需要根據具體情況決定，如果網絡請求，可能更好的是requestid、sessionid；如果是系統日志，那麼可能是程序、線程ID；如果是分布式叢集，那麼可能是副本的唯一id

　　日志記錄的事件發生的上下文環境直覺重要，能告知事件是在什麼樣的情況發生的。當然，上面提到的when、where、who都屬于上下文，這些都是固定的，通用的。而在本小節，context專指高度依賴于具體的日志内容的資訊，這些資訊，是用于定位問題的具體原因。比如

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

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

　　早期的程式設計語言提供的日志功能都比較初級，一般都是輸出到終端或者檔案，如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系統進行分析，是很多應用程式的通用做法。

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

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

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

　　比如下面的僞代碼

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

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

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

　　上面的代碼可謂麻雀雖小五髒俱全，包含了使用logging架構的方方面面。第4行是named logger，第5行設定log level，第6行指定輸出目标，第7行指定輸出格式（包括時間，logger name，log level，具體的日志内容）。

　　運作結果如下：

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

　　由于目前的log level是DEBUG，那麼第15行的日志會輸出，這是正常的。如果将第5行的log level改成INFO，那麼輸出如下：

2017-12-02 17:53:20,049 - LazyLogging - INFO - getUserCount is called

　　雖然第15行的日志沒有輸出，但這句代碼還是會執行，這就意味着：第一，一定會調用getUserCount 這個函數（上面的輸出已經證明了）；第二，即使日志内容最終不會被輸出，仍然會生成一個字元串（隻是無法驗證）。而如果根據log level不需要輸出第15行的日志，這兩步都是沒有必要的。

　　要解決第二個問題很簡單，将第15行改成

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

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

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

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

　　但是，這是非常不好的寫法！除非你們保證所調用的函數是沒有副作用的（side－effect），即函數的調用無狀态，不會改變程式的狀态，否則程式的狀态居然會依賴于log level，這是一個陷阱，一個坑，一點都不pythonic。

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

　　在網上看到這麼一句話

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

本文版權歸作者xybaby（博文位址：http://www.cnblogs.com/xybaby/）所有，歡迎轉載和商用，請在文章頁面明顯位置給出原文連結并保留此段聲明，否則保留追究法律責任的權利，其他事項，可留言咨詢。