站長資訊平臺

首頁 > 站長百科 > 網絡編程

Java小應用日志級別異常處理最佳實踐

2018-09-21 來源：importnew

原文出處：南角影

編者按：做了很多年IT工作，突然又對日志級別有些迷茫，哈哈，為什么要有又字。是的，人們都在實踐中不停的學習并增進自己。寫了好久的字，盯住看3分鐘，然后你會想，哦？寫錯了吧 ^_^

原文在：?https://stackify.com/java-logging-best-practices/?。是官方的內容，至于 ELKB，也是類似的東西。

日志：我們應該做的更好了

我在說什么？現(xiàn)在有大量的Java日志框架和庫，大多數(shù)開發(fā)人員每天都在使用。兩個最常用的是 log4j 和 logback。他們使用起來非常簡單，并且表現(xiàn)很不錯�；镜� Java 日志文件還不夠，這里我們會給出一些Java最佳實踐或者建議來幫助你去使用！

你曾經脫離開發(fā)部門去查看過日志文件嗎？如果你做過這些事情，你很快會意識到一些問題。

有大量的數(shù)據(jù)
你需要訪問數(shù)據(jù)
分布在多個服務器
一個具體的操作可能是跨應用的，因此你需要查看多個日志
日志都是流水性的，很難查詢。就算你要把數(shù)據(jù)放在SQL里面，你也需要對文本數(shù)據(jù)做全索引以便查詢。
很難閱讀。消息就像意大利面似的雜亂難以閱讀
你通常沒有任何用戶的上下文等信息
你可能缺少一些有用的細節(jié)（你的意思是說“l(fā)og.Info(‘In the method’)沒用？？？）
你需要管理日志文件循環(huán)和保留

另外，你有你應用生成的大量數(shù)據(jù)，卻不能有效的工作起來。

是時候嚴肅對待日志了

一旦你的應用不是運行在你的桌面系統(tǒng)，那么當你的應用不能正確運行的時候，日志（包括錯誤信息）就是你的救命稻草。當然，AMP（性能管理平臺）工具會對內存溢出、性能閥值出現(xiàn)問題的時候發(fā)出警告信息，但這些信息確并不能幫你解決問題，例如為什么這個用戶不能登錄，或者為什么這條記錄沒有處理

在 Stackify，我們構建了一個日志文化“culture of logging” ，來達到如下目標

輸出所有的事情。盡可能多的記錄你所能記錄的，總是有相關的上下文日志，這些日志并不會增加開銷。?
要智能工作，不要死工作。在固定位置整合所有的日志（約定，比如 d:/someapplogs/），這個位置對所有的開發(fā)人員都是透明的，并可以訪問的。從日志里面發(fā)現(xiàn)異常有助于提升我們的產品。

本文我們將分享這些最佳實踐，并分享我們是如何達到以上目標，其中大部分已經在 Stackify’s 日志管理系統(tǒng)中實現(xiàn)了。如果你使用了前綴式查看系統(tǒng)（Prefix to view your logs,），一定要去看看。

開始記錄所有的事情

我在很多商店工作過，那里的信息是這樣的

} catcha(Exception e){
    LOGGER.error(e.getMessage(),e);
}

我給這個開發(fā)人員點贊，至少使用了 try/catch 來處理異常。異常里面會包含堆棧信息讓我大概知道從那里來的這個異常，但沒有記錄更多的上下文信息。

有時，他們也做了一些前置的日志

public void processResultes(final List<Double> results){
    LOGGER.debug("Processing resultes");
}

但是，通常這樣的語句并不能告訴你應用里面到底發(fā)生了什么。如果你負責生產應用的問題解決，那么這樣的日志并不能給你什么指示，尤其還是像大海撈針似的找到這些日志。

就像之前提及的一樣。當生產出現(xiàn)問題的時候，你不能查看物力服務器上的內容，日志是解決問題最常用的幾個手段之一。你想要有大量的關聯(lián)信息及上下文信息。下面我給出指導性原則。

Walk the Code

讓我們假設你有個想要處理的 try/catch 的地方，但是之前并沒有告訴你關于請求的更多信息，樣例代碼是這樣的

public class Foo {

    private int id;

    private double value;

    public Foo(int id, double value) {
     this.id = id;
     this.value = value;
    }

    public int getId() {
     return id;
    }

    public double getValue() {
     return value;
    }

}

按照下面工廠模式創(chuàng)建 Foo 對象，注意，我留了一個可能產生錯誤的地方，方法里面調用 value.doubleValue()，但沒有檢查 null。

public class FooFactory {

    public static Foo createFoo(int id, Double value) {
     return new Foo(id, value.doubleValue());
    }

}

這是簡單有用的場景。假設這是我應用的一個關鍵場景（不允許有任何失�。�，讓我們嘗試加一些日志信息。

public class FooFactory {

    private static Logger LOGGER = LoggerFactory.getLogger(FooFactory.class);

    public static Foo createFoo(int id, Double value) {

     LOGGER.debug("Creating a Foo");

     try {
         Foo foo = new Foo(id, value.doubleValue());

         LOGGER.debug("{}", foo);

         return foo;

     } catch (Exception e) {
         LOGGER.error(e.getMessage(), e);
     }

     return null;
    }

}

現(xiàn)在我們創(chuàng)建兩個 foo 對象，一個有效，一個無效。

 FooFactory.createFoo(1, Double.valueOf(33.0));
    FooFactory.createFoo(2, null);

日志看起來是這樣的

2017-02-15 17:01:04,842 [main] DEBUG com.stackifytest.logging.FooFactory: Creating a Foo
2017-02-15 17:01:04,848 [main] DEBUG com.stackifytest.logging.FooFactory: com.stackifytest.logging.Foo@5d22bbb7
2017-02-15 17:01:04,849 [main] DEBUG com.stackifytest.logging.FooFactory: Creating a Foo
2017-02-15 17:01:04,851 [main] ERROR com.stackifytest.logging.FooFactory:
java.lang.NullPointerException
    at com.stackifytest.logging.FooFactory.createFoo(FooFactory.java:15)
    at com.stackifytest.logging.FooFactoryTest.test(FooFactoryTest.java:11)

現(xiàn)在我們知道了一些信息，當 FooFactory.createFoo() 方法時候出錯了，但沒有上下文。默認的 debug 信息打印對象 toString 不可讀，可以修改 toString。

@Override
public String toString() {
    return "Foo [id=" + id + ", value=" + value + "]";
}

修改后運行

2017-02-15 17:13:06,032 [main] DEBUG com.stackifytest.logging.FooFactory: Creating a Foo
2017-02-15 17:13:06,041 [main] DEBUG com.stackifytest.logging.FooFactory: Foo [id=1, value=33.0]
2017-02-15 17:13:06,041 [main] DEBUG com.stackifytest.logging.FooFactory: Creating a Foo
2017-02-15 17:13:06,043 [main] ERROR com.stackifytest.logging.FooFactory:
java.lang.NullPointerException
    at com.stackifytest.logging.FooFactory.createFoo(FooFactory.java:15)
    at com.stackifytest.logging.FooFactoryTest.test(FooFactoryTest.java:11)

好多了！現(xiàn)在我們可以看到 [id=, value=]。另一個可選項是你可以通過java反射來獲取對應的屬性。最主要的好處就是當你增加修改成員的時候，你不要修改 toString 方法了。下面是使用了 Google 的 Gson 庫的輸出。

2017-02-15 17:22:55,584 [main] DEBUG com.stackifytest.logging.FooFactory: Creating a Foo
2017-02-15 17:22:55,751 [main] DEBUG com.stackifytest.logging.FooFactory: {"id":1,"value":33.0}
2017-02-15 17:22:55,754 [main] DEBUG com.stackifytest.logging.FooFactory: Creating a Foo
2017-02-15 17:22:55,760 [main] ERROR com.stackifytest.logging.FooFactory:
java.lang.NullPointerException
    at com.stackifytest.logging.FooFactory.createFoo(FooFactory.java:15)
    at com.stackifytest.logging.FooFactoryTest.test(FooFactoryTest.java:11)

當你在 Stackify 的回溯工具中用 JSON 來輸出對象后，可以看到 JSON? 格式化的對象。
圖略，差不多就是移動到輸出位置，可以更方便查看對象內容。

{
  variable : value,
  variable : value
}

輸出更多的診斷上下文詳細信息

這就給我們帶來了關于記錄更多細節(jié)的最后一點:診斷上下文日志。在調試生產問題時，您可能在日志中有上千次“創(chuàng)建一個 Foo”消息，但是不知道是誰創(chuàng)建的。知道用戶是誰是一種非常珍貴的上下文，能夠快速解決問題�？紤]其他的細節(jié)可能是有用的——例如，HttpWebRequest 細節(jié)。但是誰想要記住每次都記錄下來呢？如何映射診斷上下文信息可以參考 SLF4J’s MDC?https://logback.qos.ch/manual/mdc.html。

最簡單的增加上下文選項通常在 servlet filter 中。下面這個例子創(chuàng)建了一個 servlet filter 生成事務 id 并關聯(lián)到 MDC。

public class LogContextFilter implements Filter {

    public void init(FilterConfig config) {
    }

    public void destroy() {
    }

    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws ServletException, IOException {

     String transactionId = UUID.randomUUID().toString();

     MDC.put("TRANS_ID", transactionId);

現(xiàn)在我們可以看到如下類似日志

19:49:36.350 eric-ubuntu DEBUG Create a Foo {"TRANS_ID":"d91lxxxxx2ffjjlslf03jf9j;a;j8g3g"}
19:49:36.406 eric-ubuntu DEBUG {"id":1,"value":33.0}{"TRANS_ID":"d91lxxxxx2ffjjlslf03jf9j;a;j8g3g"}

更多的上下文�，F(xiàn)在，我們可以從單個請求中跟蹤所有日志語句。

這就引出了下一個話題，那就是什么僅僅是努力工作，而不是更聰明地工作（Work Harder, Not Smarter）。但在此之前，我將回答一個我肯定會在評論中聽到的問題:“但是如果我記錄了所有東西，那就產生更多的開銷和巨大的日志文件了嗎？我的回答有幾個部分，首先使用日志冗余。你可以使用 LOGGER.debug() 輸出任何你需要的信息，而在生產上你可以輸出警告級別之上的信息。當你使用 debug 時，只需要修改屬性文件而不需要重新部署代碼。其次，日志輸出應該異步非阻塞的，開銷非常低，如果你擔心日志文件空間，下節(jié)會介紹幾個更聰明的方法去處理。

更聰明地工作，不僅僅是努力

既然我們已經記錄了所有內容，它提供了更多的上下文數(shù)據(jù)，我們將會討論下一部分內容。正如我所提到并演示了的，將所有這些輸出到平面文件中仍然不能在很大的復雜的應用程序和環(huán)境中幫助您很多。在數(shù)千個請求中，跨越數(shù)天、數(shù)周或更長時間、跨多個服務器的文件，您必須考慮如何快速找到所需的數(shù)據(jù)。

我們真的需要提供一個解決方案：
- 在一個地方聚合所有的 Log 和 Exception；
- 這些日志對團隊中所有成員可見、實時；
- 在整個堆棧/基礎結構中提供日志記錄的時間線；
- 是以結構化的格式并高度索引的存儲，利于搜索。

這是我告訴你們的關于 Stackfy Retrace的部分。當我們試圖提高自己的能力以快速有效地處理我們的日志數(shù)據(jù)時，我們決定將它作為我們產品的核心部分（是的，我們使用 Stackify 來監(jiān)控 Stackify）并與我們的客戶共享，因為我們認為這是應用程序故障排除的核心問題。

首先，我們認識到許多開發(fā)人員已經登錄了，并且不打算花大量的時間來將代碼取出并放入新的代碼。這就是為什么我們?yōu)樽畛Ｒ姷?Java 日志框架創(chuàng)建了日志應用程序。

log4j 1.2 (https://github.com/stackify/stackify-log-log4j12)
log4j 2.x (https://github.com/stackify/stackify-log-log4j2)
logback (https://github.com/stackify/stackify-log-logback)

繼續(xù)使用 log4j 作為樣例，設置非常簡單，在 pom 文件中加入

<dependency>
   <groupId>com.stackify</groupId>
   <artifactId>stackify-log-log4j12</artifactId>
   <version>1.1.9</version>
   <scope>runtime</scope>
</dependency>

當然，在 logging.properties 文件中需要加入

log4j.rootLogger=DEBUG, CONSOLE, STACKIFY

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender

log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%d [%t] %-5p %c: %m%n

log4j.appender.STACKIFY=com.stackify.log.log4j12.StackifyLogAppender
log4j.appender.STACKIFY.apiKey=[HIDDEN]
log4j.appender.STACKIFY.application=test-logging
log4j.appender.STACKIFY.environment=test

正如您所看到的，如果您已經使用了不同的 appender，您可以將它放在適當?shù)奈恢�，并將它們放在一起�，F(xiàn)在您已經將日志流到 Stackfy，我們可以查看一下日志記錄看板。（順便說一下，如果我們的監(jiān)控代理安裝了，你也可以把 Syslog 項發(fā)送到 stackfy！）

這個指示板顯示了一個整合的日志數(shù)據(jù)流，來自您的所有服務器和應用程序，呈現(xiàn)在時間軸上。從這里，你可以快速地

查看基于時間范圍的日志
對特定的服務器、應用程序或環(huán)境進行篩選

另外還有一些非常好的可用性。你會注意到的第一件事就是頂部的圖表。這是快速“分流”你的應用程序的好方法。藍色的線表示日志消息的速率，紅色條表示記錄的異常。

明顯，幾分鐘前，我的web應用程序開始有了更穩(wěn)定的活動，但更重要的是，在同一時間我們開始發(fā)現(xiàn)很多異常。異常不會開銷CPU和內存，但會對用戶的滿意度產生直接影響，這就是錢啊。

過放大到這個時間段的圖表，我可以快速地將我的日志細節(jié)過濾到那個時間范圍，并查看那段時間的日志。

查找你的日志

您是否看到下面的藍色文本看起來像一個 JSON 對象？

它是一個 JSON 對象。這是日志對象的結果，并在前面添加了上下文屬性。它看起來比平面文件中的純文本要好得多，不是嗎？它變得更棒了�？吹巾撁骓敳康乃阉骺蛄藛幔课铱梢暂斎肴魏挝夷芟氲降乃阉髯址�，它會查詢我所有的日志，就像它是一個普通文本（Plain File）一樣。但是，正如我們前面討論的那樣，這并不好，因為您最終可能會得到比您想要的更多的匹配。假設我要搜索所有帶 id 為 5 的對象。幸運的是，我們的日志聚合器非常聰明，可以在這個位置上提供幫助。

json.idNumber:5.0

搜索結果如下

想知道你還能搜索什么？當鼠標懸停在日志記錄上時，只需單擊文檔圖標，就可以看到 Stackify 索引的所有字段。能夠從日志中獲得更多的價值，并在所有字段中搜索，稱為結構化日志。

發(fā)現(xiàn) Java 異常詳情

您可能也注意到了這個紅色的 bug 圖標。這是因為我們通過自動顯示更多的上下文來區(qū)別對待異常。點擊它，我們會給出一個更深刻的觀點。

我們的庫不僅可以獲取完整的堆棧跟蹤，還可以獲取所有的 Web 請求細節(jié)，包括 header、查詢字符串和服務器變量。在這個模式中，有一個 “Logs” 選項卡，它提供了一個預先過濾的從應用程序中記錄日志的視圖，在它發(fā)生的服務器上，在異常之前和之后的一個很窄的時間窗口中，為異常提供更多的上下文。想知道這個錯誤是多么常見或頻繁，或者想查看其他事件的詳細信息？點擊“查看所有事件”按鈕，就可以看到！

我可以很快看到這個錯誤在最后一個小時發(fā)生了60次。錯誤和日志是緊密相關的，在一個應用程序中可以發(fā)生大量的日志記錄，異常有時會在噪聲中丟失。這就是為什么我們也構建了一個錯誤指示板，給您同樣的統(tǒng)一視圖，但僅限于異常。

在這里，我可以看到一些很棒的數(shù)據(jù)

在過去的幾分鐘里，我的異常率有所上升；
我的大部分錯誤都來自于我的“測試”環(huán)境——大約每小時84次；
我有幾個新的錯誤剛剛開始出現(xiàn)（如紅色三角形所示）。

你是否曾經將你的應用程序發(fā)布到生產中，并想知道 QA 漏掉了什么？（不，我說的是 QA 會錯過一個錯誤……）錯誤指示板來救援。你可以實時看到一個趨勢——大量的紅色三角形，很多新的錯誤。圖上的大峰值?也許你的使用增加了，所以以前已知的錯誤被更多地擊中；可能有一些錯誤的代碼（比如一個泄漏的SQL連接池），導致了比正常情況下更高的 SQL 超時錯誤率。

不難想象有很多不同的場景可以提供早期預警和檢測。嗯。早期預警和檢測。這引出了另一個很大的話題。

監(jiān)控

如果能在某些時候得到提醒不是很好嗎

特定應用程序或環(huán)境的錯誤率突然增加？
一個特別解決的錯誤再次發(fā)生？
你記錄的某個動作不夠頻繁，等等？

Stackify 可以做上面所有的事情，下面逐個看下

錯誤率

當我們查看錯誤指示板時，我注意到我的“測試”環(huán)境每小時有大量的錯誤。從錯誤指示板中，單擊“出錯率”，然后選擇您希望為其配置警報的應用程序/環(huán)境

我可以為“錯誤/分鐘”和“完全錯誤”配置監(jiān)視器，然后選擇“通知”選項卡來指定應該通知誰，以及如何通知。隨后，如果使用 Stackify 監(jiān)控，我還可以在這里配置其他警報:應用程序運行狀態(tài)、內存使用、性能計數(shù)器、自定義度量、ping檢查等等。

解決的錯誤和新的錯誤

早些時候，我在創(chuàng)建 Foo 對象時不檢查 null 值，從而引入了一個新的錯誤。我已經修正了這個錯誤，并通過觀察那個特定錯誤的細節(jié)來確認它。你們可以看到，上次發(fā)生在12分鐘前：

這是一個愚蠢的錯誤，但卻是一個容易犯的錯誤。我將把這個標記為“解析”，讓我做一些非�？岬氖虑�:如果它回來了，請保持警惕。通知菜單將允許我檢查我的配置，默認情況下，我將為所有的應用程序和環(huán)境同時接收新的和倒退的錯誤通知。

現(xiàn)在，如果同樣的錯誤在將來再次發(fā)生，我將會收到關于回歸的電子郵件它會顯示在儀表盤上。當你“認為”你已經解決了這個問題并且想要確定的時候，這是一個很好的自動幫助。

日志監(jiān)控

有些東西不太容易監(jiān)測。也許您有一個異步運行的關鍵流程，它成功(或失敗)的惟一記錄是日志記錄。在這篇文章的前面，我展示了針對您的結構化日志數(shù)據(jù)進行深度查詢的能力，任何查詢都可以被保存和監(jiān)視。這里有一個非常簡單的場景:我的查詢每分鐘執(zhí)行一次，我們可以監(jiān)視我們有多少匹配的記錄。