工程實踐：如何規範地列印程式日誌？
工程實踐：如何規範地列印程式日誌？
很久之前，有個朋友問我，如果一個老專案讓你接手去進行後續維護，你會先從哪裡入手、讓自己更快地上手專案？當時我沒有特別正面去回答這個朋友的問題，我說：一個老專案是否容易上手，一個非常關鍵的地方就是這個專案的日誌是否打得足夠好。因為通常來說，一個老專案相對比較穩定了，後續大概率不會有比較大的變更和改動，那麼對於這樣的專案，核心就是“維穩”。但是任何人都無法保證專案在線上執行時不會出線上故障，在出現線上問題或者故障時，如何快速止損就是第一要義，而日誌在止損過程中就扮演著非常重要的角色。日誌打的足夠明瞭清晰，可以幫助開發和運維人員快速定位問題，繼而決定採取何種方案進行止損。
今天就讓我們一起來聊一聊如何把專案程式日誌打“好”。以下是本文大綱目錄：
一.為何需要規範地列印程式日誌？
二.如何規範地列印程式日誌？
若有不正之處請多多諒解，並歡迎批評指正。
請尊重作者勞動成果，轉載請標明原文連結：
http://www.dolphin0520.com/archives/2018/11/26/176.html
一.為何需要規範地列印程式日誌？
我們平時在寫程式程式碼過程中，一般會把主要精力集中在功能實現上，往往會忽視日誌的重要性，然而日誌在系統上線後是極其重要的，因為系統上線後，只有通過日誌才能瞭解當前系統的執行狀態，在出現線上故障時，日誌是否足夠清晰明瞭決定了是否能夠快速找到止損方案。我們可以看一下下面這段程式碼：
public class HttpClient {
private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);
private static int CONNECT_TIMEOUT = 5000;// unit ms
private static int READ_TIMEOUT = 10000;// unit ms
public static String sendPost(String url, String param) {
OutputStream out = null;
BufferedReader in = null;
String result = "";
try {
URL realUrl = new URL(url);
URLConnection conn = realUrl.openConnection();
conn.setDoInput(true);
conn.setDoOutput(true);
conn.setConnectTimeout(CONNECT_TIMEOUT);
conn.setReadTimeout(READ_TIMEOUT);
conn.setRequestProperty("charset", "UTF-8");
out = new PrintWriter(conn.getOutputStream());
out.print(parm);
out.flush();
in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
String line;
while ((line = in.readLine()) != null) {
result += line;
}
} catch (Exception ex) {
LOG.error("post request error!!!");
} finally {
try {
if (out != null) {
out.close();
}
if (in != null) {
in.close();
}
} catch (IOException ex) {
LOG.error("close stream error!!!");
}
return result;
}
}
}複製程式碼
某一天線上突然大量http請求失敗，然後檢視日誌，發現了大量的“post request error!!!”錯誤，此時假如看到這樣的日誌你可能完全不知道究竟是什麼原因導致的，還得繼續通過一些其他的手段來定位具體原因。
假如列印的錯誤日誌是這樣的：
post request error!!!, url:[http://www.123.test.com], param:[name=jack] java.net.ConnectException: Connection refused at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:579)複製程式碼
那麼便能很快地斷定是下游http服務問題導致的，且下游http服務域名為www.123.test.com(Connection refused通常是由於下游服務埠未啟動引起的)，可以迅速找相應的人員進行止損，避免在故障定位階段耗費大量的時間。
上面舉的例子只是一個非常小的例子，實際日常開發中可能碰到的線上問題比這個更加複雜和棘手，總結來看，日誌的主要作用有以下幾點：
1）日誌是系統執行的“照妖鏡”，通過它能夠實時反映系統的執行狀態；
如上圖所示，系統A中producer不斷產生資料放入到data queue中，sender不斷從data queue中取資料傳送給下游系統B的receiver，那麼對於系統A來說，data queue中的待發送資料量便是一個非常關鍵的指標，它能夠從側面真實反應當前系統的執行狀況，如果data queue中的element個數超過容量的90%了，那麼標誌著此時系統可能執行不正常了，會有佇列堵塞的風險；如果data queue中的element個數不到容量的10%，那麼標誌著此時系統執行比較正常，出現佇列堵塞的風險較低。
如果這個指標沒有輸出到日誌中，開發和運維人員是無法確切知道當前系統A的執行狀態的(當然也有其他的方式來獲取這個指標，比如通過http介面暴露出來也是一種方式之一)。
2）良好的日誌便於後期運維和開發人員迅速定位線上問題，加快止損速度，減少系統故障帶來的損失；
3）日誌還有另外一個作用便是能夠無縫與監控系統結合，通過監控系統進行日誌採集，拿到系統執行的相關效能指標，有利於分析系統的效能瓶頸、提前規避風險；
舉例說明：
假如有一個商城系統，在初期，資料庫通過2臺伺服器提供服務(1臺master，1臺slave)，此時大部分介面能在秒級內響應使用者請求。隨著時間的推移，商城系統的使用者量逐漸增多，併發查詢和寫入量都出現了一定的增長，資料庫中的資料量也慢慢增多，導致部分sql語句查詢越來越慢，突然有一天，資料庫的slave機器由於過多的慢查詢導致被拖垮，徹底宕機了，導致商城服務不可用。
如果商城系統在日誌中記錄了每個http請求的耗時情況，通過監控系統配置日誌採集，同時配置相應的報警，那麼便能提前發現由於業務增長帶來的系統性能瓶頸，提前進行系統優化(如機器擴容、sql語句優化、分庫分表等)，規避風險。
4）便於統計與業務相關的指標資料，進行相關業務分析和功能優化。
舉例說明：
比如一個搜尋系統，想統計過去一週不同地域(如南北地域)的搜尋使用佔比，如果日誌中本身列印了每個搜尋query請求的ip，則很容易統計，否則需要重新上線加日誌才能統計。
因此，大家在日常編寫程式碼過程中要注重日誌書寫的規範性，讓它發揮出它應有的價值，在輔助保障我們服務穩定執行的同時，能夠有效提升後期系統維護效率。
二.如何規範地列印程式日誌？
接下來，我們從以下幾個方面來談談如何規範地列印日誌。
2.1 日誌檔案命名
通常來說日誌檔案的命名可包括以下幾個關鍵資訊：
型別標識(logTypeName) 日誌級別(logLevel) 日誌生成時間(logCreateTime) 日誌備份編號(logBackupNum)複製程式碼
型別標識 ：指此日誌檔案的功能或者用途，比如一個web服務，記錄http請求的日誌通常命名為request.log或者access.log，request、access就是型別標識，而java的gc日誌通常命名為gc.log，這樣看一目瞭然；而通常用來記錄服務的整體執行的日誌一般用服務名稱(serviceName、appKey)或者機器名(hostName)來命名，如 nginx.log；
日誌級別 ：列印日誌的時候直接通過檔案來區分級別是一種比較推薦的方式，如果把所有級別的日誌打到同一個日誌檔案中，在定位問題時，還需要去檔案中進行查詢操作，相對繁瑣。日誌級別一般包括DEBUG、INFO、WARN、ERROR、FATAL這五個級別，在實際編寫程式碼中，可以採取嚴格匹配模式或者非嚴格匹配模式，嚴格匹配模式即INFO日誌檔案中只打印INFO日誌，ERROR日誌檔案只打印ERROR日誌；非嚴格匹配模式即INFO日誌檔案可以列印INFO日誌、WARN日誌、ERROR日誌、FATAL日誌，WARN日誌檔案可以列印WARN日誌、ERROR日誌、FATAL日誌，以此類推。
日誌生成時間 ：即在日誌檔名稱中附帶上日誌檔案建立的時間，方便在查詢日誌檔案時進行排序；
日誌備份編號 ：當進行日誌切割時，如果是以檔案大小進行滾動，此時可以在日誌檔名稱末尾加上編號；
2.2 日誌滾動
雖然日誌中能夠儲存系統執行時的關鍵資訊，但是由於磁碟空間有限，所以我們不能無限制地保留日誌，因此必須有日誌滾動策略。日誌滾動通常有以下幾種模式：
第一種：按照時間滾動
第二種：按照單個日誌檔案大小滾動
第三種：同時按照時間和單個日誌檔案大小滾動。
- 按照時間滾動，即每隔一定的時間建立一個新的日誌檔案，通常可以按照小時級別滾動或者天級別滾動，具體採取哪種方式取決於系統日誌的列印量。如果系統日誌比較少，可以採取天級別滾動；而如果系統日常量比較大，則建議採取小時級別滾動。
- 按照單個日誌檔案大小滾動，即每當日誌檔案達到一定大小則建立一個新的日誌檔案，通常建議單個日誌檔案大小不要超過500M，日誌檔案過大的話，對於日誌監控或者問題定位排查都可能會造成一定影響。
- 按照時間和單個日誌檔案大小滾動，這種模式通常適用於希望保留一定時間的日誌，但是又不希望單個日誌檔案過大的場景。比如logback就提供了這種配置模式，可參考： logback.qos.ch/manual/appe…
對於日誌滾動策略來說，有2個比較關鍵的引數：最大保留日誌數量和最大磁碟佔用空間。這2個引數切記一定要設定，如果沒有設定，則很有可能會出現把線上機器磁碟打滿的情況。
2.3 日誌級別
日誌的級別通常有以下幾種：
debug/trace、info、warning、error、fatal
這幾種日誌級別的嚴重程式依次遞增：
debug/trace ：debug和trace級別的日誌由於列印內容較多，所以通常情況下不適用於線上生產環境使用，一般使用於前期線下環境除錯。即使線上環境要使用，也需要通過開關來控制，只在定位追蹤線上問題時才開啟；
info ：info日誌一般用來記錄系統執行的關鍵狀態、關鍵業務邏輯或者關鍵執行節點。但切記一點，info日誌絕不可濫用，如果info日誌濫用，則和debug/trace日誌沒有太大區別了。
warning： warning日誌一般用來記錄系統執行時的一些非預期情況，顧名思義，是作為一種警示，提醒開發和運維人員需要關注，但是不用人為介入立刻去處理的。
error ：error日誌一般用來記錄系統執行時的一些普通錯誤，這些錯誤一旦出現，則表示已經影響了使用者的正常訪問或者使用，通常意味著需要人為介入處理。但很多時候在生產環境中，也不一定是出現error日誌就需要人工立即介入處理的，通常會結合error日誌的數量以及持續時間來進行綜合判斷。
fatal ：屬於系統致命錯誤，一般出現意味著系統基本等於掛掉了，需要人工立即介入處理。
下面舉個簡單的例子來說明，假如我們有這樣一個場景，我們有一個工資計算系統，每隔月1號需要從員工考勤系統獲取公司所有員工的考勤資料，然後根據考勤資料來計算上月應發工資，那麼需要有一個函式從考勤系統獲取員工考勤資料：
public Map<Long, Double> getEmployeeWorkDaysFromAttendance(int year, int month, Set<Long> employeeList) throws BusiessException {
// 入口關鍵日誌，需要列印關鍵的引數，因為employeeList可能數量較大，所以次數沒有直接列印employeeList列表內容，只打印了size
logger.info("get employee work days, year:{}, month:{}, employeeList.size:{}", year, month, employeeList.size());
// 如果需要臨時檢驗員工列表，可以把debug日誌開關開啟
if (debugOpen()) {
logger.debug("employ list content:{}", JSON.toJsonString(employeeList));
}
int retry = 1;
while (retry <= MAX_RETRY_TIMES) {
try {
Map<Long, Double> employeeWorkDays = employeeAttendanceRPC.getEmployeeWorkDays(year, month, employeeList);
logger.info("get employee work days success, year:{}, month:{}, employeeList.size:{}, employeeWorkDays.size:{}", year, month, employeeList.size(), employeeWorkDays.size());
return employeeWorkDays;
} catch (Exception ex) {
logger.warning("rpc invoke failed(employeeAttendanceRPC.getEmployeeWorkDays), retry times:{}, year：{}, month:{},employeeList.size:{}", retry, year, month, employeeList.size(), ex);
// 連續重試失敗之後，向上跑出異常
// 對於沒有異常機制的語言，此處應該列印error日誌
if (retry == MAX_RETRY_TIMES) {
throw new BusiessException(ex, "rpc invoke failed(employeeAttendanceRPC.getEmployeeWorkDays)");
}
}
retry++;
}
}複製程式碼
2.4 日誌列印時機的選擇
由於日誌是為了方便我們瞭解系統當前的執行狀況以及定位線上問題，所以日誌列印的時機非常重要，如果濫用日誌，則會導致日誌內容過多，影響問題定位的效率；如果日誌列印過少，則容易導致缺少關鍵日誌，導致在線上定位問題時找不到問題根音。因此把握日誌列印的時機至關重要，以下是常見的適合列印日誌的時機：
1）http呼叫或者rpc介面呼叫
在程式呼叫其他服務或者系統的時候，需要列印介面呼叫引數和呼叫結果(成功/失敗)。
2）程式異常
在程式出現exception的時候，要麼選擇向上丟擲異常，要麼必須在catch塊中列印異常堆疊資訊。不過需要注意的是，最好不要重複列印異常日誌，比如在catch塊裡既向上丟擲了異常，又去列印錯誤日誌(對外rpc介面函式入口處除外)。
3）特殊的條件分支
程式進入到一些特殊的條件分支時，比如特殊的else或者switch分支。比如我們根據工齡計算薪資：
public double calSalaryByWorkingAge(int age) {
if (age < 0) {
logger.error("wrong age value, age:{}", age);
return 0;
}
// ..
}複製程式碼
理論上工齡不可能小於0，所以需要打印出這種非預期情況，當然通過丟擲異常的方式也是可行的。
4）關鍵執行路徑及中間狀態
在一些關鍵的執行路徑以及中間狀態也需要記錄下關鍵日誌資訊，比如一個演算法可能分為很多步驟，每隔步驟的中間輸出結果是什麼，需要記錄下來，以方便後續定位跟蹤演算法執行狀態。
5）請求入口和出口
在函式或者對外介面的入口/出口處需要列印入口/出口日誌，一來方便後續進行日誌統計，同時也更加方便進行系統執行狀態的監控。
2.5 日誌內容與格式
日誌列印時機決定了能夠根據日誌去進行問題定位，而日誌的內容決定了是否能夠根據日誌快速找出問題原因，因此日誌內容也是至關重要的。通常來說，一行日誌應該至少包括以下幾個組成部分：
logTag、param、exceptionStacktrace
logTag為日誌標識，用來標識此日誌輸出的場景或者原因，param為函式呼叫引數，exceptionStacktrace為異常堆疊。舉例說明：
- good case
public class HttpClient {
private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);
private static int CONNECT_TIMEOUT = 5000;// unit ms
private static int READ_TIMEOUT = 10000;// unit ms
public static String sendPost(String url, String param) {
OutputStream out = null;
BufferedReader in = null;
String result = "";
try {
URL realUrl = new URL(url);
URLConnection conn = realUrl.openConnection();
conn.setDoInput(true);
conn.setDoOutput(true);
conn.setConnectTimeout(CONNECT_TIMEOUT);
conn.setReadTimeout(READ_TIMEOUT);
conn.setRequestProperty("charset", "UTF-8");
out = new PrintWriter(conn.getOutputStream());
out.print(parm);
out.flush();
in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
String line;
while ((line = in.readLine()) != null) {
result += line;
}
} catch (Exception ex) {
// 有關鍵logTag，有引數資訊，有錯誤堆疊
LOG.error("post request error!!!, url:[[}], param:[{}]", url, param, ex);
} finally {
try {
if (out != null) {
out.close();
}
if (in != null) {
in.close();
}
} catch (IOException ex) {
LOG.error("close stream error!!!, url:[[}], param:[{}]", url, param, ex);
}
return result;
}
}
}
複製程式碼
- bad case
public class HttpClient {
private static final Logger LOG = LoggerFactory.getLogger(HttpClient.class);
private static int CONNECT_TIMEOUT = 5000;// unit ms
private static int READ_TIMEOUT = 10000;// unit ms
public static String sendPost(String url, String param) {
OutputStream out = null;
BufferedReader in = null;
String result = "";
try {
URL realUrl = new URL(url);
URLConnection conn = realUrl.openConnection();
conn.setDoInput(true);
conn.setDoOutput(true);
conn.setConnectTimeout(CONNECT_TIMEOUT);
conn.setReadTimeout(READ_TIMEOUT);
conn.setRequestProperty("charset", "UTF-8");
out = new PrintWriter(conn.getOutputStream());
out.print(parm);
out.flush();
in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
String line;
while ((line = in.readLine()) != null) {
result += line;
}
} catch (Exception ex) {
// 沒有任何錯誤資訊
LOG.error("post request error!!!");
} finally {
try {
if (out != null) {
out.close();
}
if (in != null) {
in.close();
}
} catch (IOException ex) {
LOG.error("close stream error!!!");
}
return result;
}
}
}
複製程式碼
另外，對於對外http介面或者rpc介面， 最好對於每個請求都有requestId ，以便跟蹤每個請求後續所有的執行路徑。