很久之前，有個朋友問我，如果一個老項(xiàng)目讓你接手去進(jìn)行后續(xù)維護(hù)，你會先從哪里入手、讓自己更快地上手項(xiàng)目？當(dāng)時我沒有特別正面去回答這個朋友的問題，我說：一個老項(xiàng)目是否容易上手，一個非常關(guān)鍵的地方就是這個項(xiàng)目的日志是否打得足夠好。因?yàn)橥ǔ碚f，一個老項(xiàng)目相對比較穩(wěn)定了，后續(xù)大概率不會有比較大的變更和改動，那么對于這樣的項(xiàng)目，核心就是“維穩(wěn)”。但是任何人都無法保證項(xiàng)目在線上運(yùn)行時不會出線上故障，在出現(xiàn)線上問題或者故障時，如何快速止損就是第一要義，而日志在止損過程中就扮演著非常重要的角色。日志打的足夠明了清晰，可以幫助開發(fā)和運(yùn)維人員快速定位問題，繼而決定采取何種方案進(jìn)行止損。

今天就讓我們一起來聊一聊如何把項(xiàng)目程序日志打“好”。

一.為何需要規(guī)范地打印程序日志？

我們平時在寫程序代碼過程中，一般會把主要精力集中在功能實(shí)現(xiàn)上，往往會忽視日志的重要性，然而日志在系統(tǒng)上線后是極其重要的，因?yàn)橄到y(tǒng)上線后，只有通過日志才能了解當(dāng)前系統(tǒng)的運(yùn)行狀態(tài)，在出現(xiàn)線上故障時，日志是否足夠清晰明了決定了是否能夠快速找到止損方案。我們可以看一下下面這段代碼：

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請求失敗，然后查看日志，發(fā)現(xiàn)了大量的“post request error!!!”錯誤，此時假如看到這樣的日志你可能完全不知道究竟是什么原因?qū)е碌?，還得繼續(xù)通過一些其他的手段來定位具體原因。

假如打印的錯誤日志是這樣的：

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)

那么便能很快地?cái)喽ㄊ窍掠蝖ttp服務(wù)問題導(dǎo)致的，且下游http服務(wù)域名為www.123.test.com(Connection refused通常是由于下游服務(wù)端口未啟動引起的)，可以迅速找相應(yīng)的人員進(jìn)行止損，避免在故障定位階段耗費(fèi)大量的時間。

上面舉的例子只是一個非常小的例子，實(shí)際日常開發(fā)中可能碰到的線上問題比這個更加復(fù)雜和棘手，總結(jié)來看，日志的主要作用有以下幾點(diǎn)：

1）日志是系統(tǒng)運(yùn)行的“照妖鏡”，通過它能夠?qū)崟r反映系統(tǒng)的運(yùn)行狀態(tài)；

如上圖所示，系統(tǒng)A中producer不斷產(chǎn)生數(shù)據(jù)放入到data queue中，sender不斷從data queue中取數(shù)據(jù)發(fā)送給下游系統(tǒng)B的receiver，那么對于系統(tǒng)A來說，data queue中的待發(fā)送數(shù)據(jù)量便是一個非常關(guān)鍵的指標(biāo)，它能夠從側(cè)面真實(shí)反應(yīng)當(dāng)前系統(tǒng)的運(yùn)行狀況，如果data queue中的element個數(shù)超過容量的90%了，那么標(biāo)志著此時系統(tǒng)可能運(yùn)行不正常了，會有隊(duì)列堵塞的風(fēng)險(xiǎn)；如果data queue中的element個數(shù)不到容量的10%，那么標(biāo)志著此時系統(tǒng)運(yùn)行比較正常，出現(xiàn)隊(duì)列堵塞的風(fēng)險(xiǎn)較低。

如果這個指標(biāo)沒有輸出到日志中，開發(fā)和運(yùn)維人員是無法確切知道當(dāng)前系統(tǒng)A的運(yùn)行狀態(tài)的(當(dāng)然也有其他的方式來獲取這個指標(biāo)，比如通過http接口暴露出來也是一種方式之一)。

2）良好的日志便于后期運(yùn)維和開發(fā)人員迅速定位線上問題，加快止損速度，減少系統(tǒng)故障帶來的損失；

3）日志還有另外一個作用便是能夠無縫與監(jiān)控系統(tǒng)結(jié)合，通過監(jiān)控系統(tǒng)進(jìn)行日志采集，拿到系統(tǒng)運(yùn)行的相關(guān)性能指標(biāo)，有利于分析系統(tǒng)的性能瓶頸、提前規(guī)避風(fēng)險(xiǎn)；

舉例說明：

假如有一個商城系統(tǒng)，在初期，數(shù)據(jù)庫通過2臺服務(wù)器提供服務(wù)(1臺master，1臺slave)，此時大部分接口能在秒級內(nèi)響應(yīng)用戶請求。隨著時間的推移，商城系統(tǒng)的用戶量逐漸增多，并發(fā)查詢和寫入量都出現(xiàn)了一定的增長，數(shù)據(jù)庫中的數(shù)據(jù)量也慢慢增多，導(dǎo)致部分sql語句查詢越來越慢，突然有一天，數(shù)據(jù)庫的slave機(jī)器由于過多的慢查詢導(dǎo)致被拖垮，徹底宕機(jī)了，導(dǎo)致商城服務(wù)不可用。

如果商城系統(tǒng)在日志中記錄了每個http請求的耗時情況，通過監(jiān)控系統(tǒng)配置日志采集，同時配置相應(yīng)的報(bào)警，那么便能提前發(fā)現(xiàn)由于業(yè)務(wù)增長帶來的系統(tǒng)性能瓶頸，提前進(jìn)行系統(tǒng)優(yōu)化(如機(jī)器擴(kuò)容、sql語句優(yōu)化、分庫分表等)，規(guī)避風(fēng)險(xiǎn)。

4）便于統(tǒng)計(jì)與業(yè)務(wù)相關(guān)的指標(biāo)數(shù)據(jù)，進(jìn)行相關(guān)業(yè)務(wù)分析和功能優(yōu)化。

舉例說明：

比如一個搜索系統(tǒng)，想統(tǒng)計(jì)過去一周不同地域(如南北地域)的搜索使用占比，如果日志中本身打印了每個搜索query請求的ip，則很容易統(tǒng)計(jì)，否則需要重新上線加日志才能統(tǒng)計(jì)。

因此，大家在日常編寫代碼過程中要注重日志書寫的規(guī)范性，讓它發(fā)揮出它應(yīng)有的價(jià)值，在輔助保障我們服務(wù)穩(wěn)定運(yùn)行的同時，能夠有效提升后期系統(tǒng)維護(hù)效率。

二.如何規(guī)范地打印程序日志？

接下來，我們從以下幾個方面來談?wù)勅绾我?guī)范地打印日志。

2.1 日志文件命名

通常來說日志文件的命名可包括以下幾個關(guān)鍵信息：

• 類型標(biāo)識(logTypeName)
• 日志級別(logLevel)
• 日志生成時間(logCreateTime)
• 日志備份編號(logBackupNum)
  

類型標(biāo)識：指此日志文件的功能或者用途，比如一個web服務(wù)，記錄http請求的日志通常命名為request.log或者access.log，request、access就是類型標(biāo)識，而java的gc日志通常命名為gc.log，這樣看一目了然；而通常用來記錄服務(wù)的整體運(yùn)行的日志一般用服務(wù)名稱(serviceName、appKey)或者機(jī)器名(hostName)來命名，如 nginx.log；

日志級別：打印日志的時候直接通過文件來區(qū)分級別是一種比較推薦的方式，如果把所有級別的日志打到同一個日志文件中，在定位問題時，還需要去文件中進(jìn)行查找操作，相對繁瑣。日志級別一般包括DEBUG、INFO、WARN、ERROR、FATAL這五個級別，在實(shí)際編寫代碼中，可以采取嚴(yán)格匹配模式或者非嚴(yán)格匹配模式，嚴(yán)格匹配模式即INFO日志文件中只打印INFO日志，ERROR日志文件只打印ERROR日志；非嚴(yán)格匹配模式即INFO日志文件可以打印INFO日志、WARN日志、ERROR日志、FATAL日志，WARN日志文件可以打印WARN日志、ERROR日志、FATAL日志，以此類推。

日志生成時間：即在日志文件名稱中附帶上日志文件創(chuàng)建的時間，方便在查找日志文件時進(jìn)行排序；

日志備份編號：當(dāng)進(jìn)行日志切割時，如果是以文件大小進(jìn)行滾動，此時可以在日志文件名稱末尾加上編號；

2.2 日志滾動

　　雖然日志中能夠保存系統(tǒng)運(yùn)行時的關(guān)鍵信息，但是由于磁盤空間有限，所以我們不能無限制地保留日志，因此必須有日志滾動策略。日志滾動通常有以下幾種模式：

　　第一種：按照時間滾動

　　第二種：按照單個日志文件大小滾動

　　第三種：同時按照時間和單個日志文件大小滾動。

按照時間滾動，即每隔一定的時間建立一個新的日志文件，通?？梢园凑招r級別滾動或者天級別滾動，具體采取哪種方式取決于系統(tǒng)日志的打印量。如果系統(tǒng)日志比較少，可以采取天級別滾動；而如果系統(tǒng)日常量比較大，則建議采取小時級別滾動。
按照單個日志文件大小滾動，即每當(dāng)日志文件達(dá)到一定大小則建立一個新的日志文件，通常建議單個日志文件大小不要超過500M，日志文件過大的話，對于日志監(jiān)控或者問題定位排查都可能會造成一定影響。
按照時間和單個日志文件大小滾動，這種模式通常適用于希望保留一定時間的日志，但是又不希望單個日志文件過大的場景。比如logback就提供了這種配置模式，可參考：https://logback.qos.ch/manual/appenders.html#SizeAndTimeBasedFNATP
　　對于日志滾動策略來說，有2個比較關(guān)鍵的參數(shù)：最大保留日志數(shù)量和最大磁盤占用空間。這2個參數(shù)切記一定要設(shè)置，如果沒有設(shè)置，則很有可能會出現(xiàn)把線上機(jī)器磁盤打滿的情況。

2.3 日志級別

　　日志的級別通常有以下幾種：

　　debug/trace、info、warning、error、fatal

　　這幾種日志級別的嚴(yán)重程序依次遞增：

　　debug/trace：debug和trace級別的日志由于打印內(nèi)容較多，所以通常情況下不適用于線上生產(chǎn)環(huán)境使用，一般使用于前期線下環(huán)境調(diào)試。即使線上環(huán)境要使用，也需要通過開關(guān)來控制，只在定位追蹤線上問題時才開啟；

　　info：info日志一般用來記錄系統(tǒng)運(yùn)行的關(guān)鍵狀態(tài)、關(guān)鍵業(yè)務(wù)邏輯或者關(guān)鍵執(zhí)行節(jié)點(diǎn)。但切記一點(diǎn)，info日志絕不可濫用，如果info日志濫用，則和debug/trace日志沒有太大區(qū)別了。

　　warning：warning日志一般用來記錄系統(tǒng)運(yùn)行時的一些非預(yù)期情況，顧名思義，是作為一種警示，提醒開發(fā)和運(yùn)維人員需要關(guān)注，但是不用人為介入立刻去處理的。

　　error：error日志一般用來記錄系統(tǒng)運(yùn)行時的一些普通錯誤，這些錯誤一旦出現(xiàn)，則表示已經(jīng)影響了用戶的正常訪問或者使用，通常意味著需要人為介入處理。但很多時候在生產(chǎn)環(huán)境中，也不一定是出現(xiàn)error日志就需要人工立即介入處理的，通常會結(jié)合error日志的數(shù)量以及持續(xù)時間來進(jìn)行綜合判斷。

　　fatal：屬于系統(tǒng)致命錯誤，一般出現(xiàn)意味著系統(tǒng)基本等于掛掉了，需要人工立即介入處理。

　　下面舉個簡單的例子來說明，假如我們有這樣一個場景，我們有一個工資計(jì)算系統(tǒng)，每隔月1號需要從員工考勤系統(tǒng)獲取公司所有員工的考勤數(shù)據(jù)，然后根據(jù)考勤數(shù)據(jù)來計(jì)算上月應(yīng)發(fā)工資，那么需要有一個函數(shù)從考勤系統(tǒng)獲取員工考勤數(shù)據(jù)：

public Map<Long, Double> getEmployeeWorkDaysFromAttendance(int year, int month, Set<Long> employeeList) throws BusiessException {
    // 入口關(guān)鍵日志，需要打印關(guān)鍵的參數(shù)，因?yàn)閑mployeeList可能數(shù)量較大，所以次數(shù)沒有直接打印employeeList列表內(nèi)容，只打印了size
    logger.info("get employee work days, year:{}, month:{}, employeeList.size:{}", year, month, employeeList.size());
 
    // 如果需要臨時檢驗(yàn)員工列表，可以把debug日志開關(guān)打開
    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);
         
        // 連續(xù)重試失敗之后，向上跑出異常
        // 對于沒有異常機(jī)制的語言，此處應(yīng)該打印error日志
        if (retry == MAX_RETRY_TIMES) {
          throw new BusiessException(ex, "rpc invoke failed(employeeAttendanceRPC.getEmployeeWorkDays)");
        }
      }
      retry++;
    }
  }

2.4 日志打印時機(jī)的選擇
　　由于日志是為了方便我們了解系統(tǒng)當(dāng)前的運(yùn)行狀況以及定位線上問題，所以日志打印的時機(jī)非常重要，如果濫用日志，則會導(dǎo)致日志內(nèi)容過多，影響問題定位的效率；如果日志打印過少，則容易導(dǎo)致缺少關(guān)鍵日志，導(dǎo)致在線上定位問題時找不到問題根音。因此把握日志打印的時機(jī)至關(guān)重要，以下是常見的適合打印日志的時機(jī)：

1）http調(diào)用或者rpc接口調(diào)用

　　在程序調(diào)用其他服務(wù)或者系統(tǒng)的時候，需要打印接口調(diào)用參數(shù)和調(diào)用結(jié)果(成功/失敗)。

2）程序異常

　　在程序出現(xiàn)exception的時候，要么選擇向上拋出異常，要么必須在catch塊中打印異常堆棧信息。不過需要注意的是，最好不要重復(fù)打印異常日志，比如在catch塊里既向上拋出了異常，又去打印錯誤日志(對外rpc接口函數(shù)入口處除外)。

3）特殊的條件分支

　　程序進(jìn)入到一些特殊的條件分支時，比如特殊的else或者switch分支。比如我們根據(jù)工齡計(jì)算薪資：

public double calSalaryByWorkingAge(int age) {
    if (age < 0) {
      logger.error("wrong age value, age:{}", age);
      return 0;
    }
    // ..
  }

　　理論上工齡不可能小于0，所以需要打印出這種非預(yù)期情況，當(dāng)然通過拋出異常的方式也是可行的。

4）關(guān)鍵執(zhí)行路徑及中間狀態(tài)

　　在一些關(guān)鍵的執(zhí)行路徑以及中間狀態(tài)也需要記錄下關(guān)鍵日志信息，比如一個算法可能分為很多步驟，每隔步驟的中間輸出結(jié)果是什么，需要記錄下來，以方便后續(xù)定位跟蹤算法執(zhí)行狀態(tài)。

5）請求入口和出口

　　在函數(shù)或者對外接口的入口/出口處需要打印入口/出口日志，一來方便后續(xù)進(jìn)行日志統(tǒng)計(jì)，同時也更加方便進(jìn)行系統(tǒng)運(yùn)行狀態(tài)的監(jiān)控。

2.5 日志內(nèi)容與格式

　　日志打印時機(jī)決定了能夠根據(jù)日志去進(jìn)行問題定位，而日志的內(nèi)容決定了是否能夠根據(jù)日志快速找出問題原因，因此日志內(nèi)容也是至關(guān)重要的。通常來說，一行日志應(yīng)該至少包括以下幾個組成部分：

　　logTag、param、exceptionStacktrace

　　logTag為日志標(biāo)識，用來標(biāo)識此日志輸出的場景或者原因，param為函數(shù)調(diào)用參數(shù)，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) {
        // 有關(guān)鍵logTag，有參數(shù)信息，有錯誤堆棧
        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，以便跟蹤每個請求后續(xù)所有的執(zhí)行路徑。

以上就是本文的全部內(nèi)容，希望對大家的學(xué)習(xí)有所幫助，也希望大家多多支持腳本之家。