工程實踐：如何規范地打印程序日志？
很久之前，有個朋友問我，如果一個老項目讓你接手去進行后續維護，你會先從哪里入手、讓自己更快地上手項目？當時我沒有特別正面去回答這個朋友的問題，我說：一個老項目是否容易上手，一個非常關鍵的地方就是這個項目的日志是否打得足夠好。因為通常來說，一個老項目相對比較穩定了，后續大概率不會有比較大的變更和改動，那么對於這樣的項目，核心就是“維穩”。但是任何人都無法保證項目在線上運行時不會出線上故障，在出現線上問題或者故障時，如何快速止損就是第一要義，而日志在止損過程中就扮演着非常重要的角色。日志打的足夠明了清晰，可以幫助開發和運維人員快速定位問題，繼而決定采取何種方案進行止損。
今天就讓我們一起來聊一聊如何把項目程序日志打“好”。以下是本文大綱目錄：
一.為何需要規范地打印程序日志？
二.如何規范地打印程序日志？
若有不正之處請多多諒解，並歡迎批評指正。
請尊重作者勞動成果，轉載請標明原文鏈接：
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就提供了這種配置模式，可參考：https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedFNATP
對於日志滾動策略來說，有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，以便跟蹤每個請求后續所有的執行路徑。
最后，推薦一下海子開通的微信公眾號，歡迎大家關注：
參考文章：
https://zhuanlan.zhihu.com/p/27363484
https://blog.csdn.net/zollty/article/details/53958428
https://www.jianshu.com/p/59cd61eb93c2
https://www.jianshu.com/p/6149463aec94
http://blog.jobbole.com/56574/
https://www.cnblogs.com/kofxxf/p/3713472.html
https://gitbook.cn/books/5ae6883ce9a7f01a861df619/index.html
https://www.cnblogs.com/xybaby/p/7954610.html
http://blog.didispace.com/cxy-wsm-zml-4/
https://www.kancloud.cn/digest/javabug/138401
https://blog.csdn.net/bad_yu/article/details/81035862