Java Spring Boot 項(xiàng)目中使用結(jié)構(gòu)化日志節(jié)省時(shí)間
【注】本文譯自：?Saving Time with Structured Logging - Reflectoring（
https://reflectoring.io/structured-logging/）
日志記錄是調(diào)查事件和了解應(yīng)用程序中發(fā)生的事情的終極資源。每個應(yīng)用程序都有某種類型的日志。
然而，這些日志通常很混亂，分析它們需要付出很多努力。在本文中，我們將研究如何利用結(jié)構(gòu)化日志來大大增加日志的價(jià)值。
我們將通過一些非常實(shí)用的技巧來提高應(yīng)用程序日志數(shù)據(jù)的價(jià)值，并使用?Logz.io?作為日志平臺來查詢?nèi)罩尽?/p>
?代碼示例
本文附有?GitHub 上（
https://github.com/thombergs/code-examples/tree/master/logging/structured-logging）的工作代碼示例。
什么是結(jié)構(gòu)化日志？
“正?！比罩臼欠墙Y(jié)構(gòu)化的。它們通常包含一個消息字符串：
2021-08-08 18:04:14.721 INFO 12402 --- [ main] i.r.s.StructuredLoggingApplication : Started StructuredLoggingApplication in 0.395 seconds (JVM running for 0.552)
此消息包含我們在調(diào)查事件或分析問題時(shí)希望獲得的所有信息：
日志事件的日期
創(chuàng)建日志事件的記錄器的名稱，以及
日志消息本身。
所有信息都在該日志消息中，但很難查詢這些信息！由于所有信息都在一個字符串中，如果我們想從日志中獲取特定信息，就必須解析和搜索這個字符串。
例如，如果我們只想查看特定記錄器的日志，則日志服務(wù)器必須解析所有日志消息，檢查它們是否具有識別記錄器的特定模式，然后根據(jù)所需的記錄器過濾日志消息。
結(jié)構(gòu)化日志包含相同的信息，但采用結(jié)構(gòu)化形式而不是非結(jié)構(gòu)化字符串。通常，結(jié)構(gòu)化日志以 JSON 格式呈現(xiàn)：
{ ? ?"timestamp": "2021-08-08 18:04:14.721", ? ?"level": "INFO", ? ?"logger": "io.reflectoring....StructuredLoggingApplication", ? ?"thread": "main", ? ?"message": "Started StructuredLoggingApplication ..."}
這種 JSON 結(jié)構(gòu)允許日志服務(wù)器有效地存儲，更重要的是檢索日志。
例如，現(xiàn)在可以通過?timestamp?或?logger?輕松過濾日志，而且搜索比解析特定模式的字符串更有效。
但是結(jié)構(gòu)化日志的價(jià)值并不止于此：我們可以根據(jù)需要向結(jié)構(gòu)化日志事件中添加任何自定義字段！?我們可以添加上下文信息來幫助我們識別問題，或者我們可以向日志添加指標(biāo)。
憑借我們現(xiàn)在觸手可及的所有數(shù)據(jù)，我們可以創(chuàng)建強(qiáng)大的日志查詢和儀表板，即使我們剛在半夜醒來調(diào)查事件，我們也能找到所需的信息。
現(xiàn)在讓我們看幾個用例，它們展示了結(jié)構(gòu)化日志記錄的強(qiáng)大功能。
為所有日志事件添加代碼路徑
我們首先要看的是代碼路徑。每個應(yīng)用程序通常有幾個不同的路徑，傳入請求可以通過應(yīng)用程序?？紤]這個圖：
此示例具有（至少）三種不同的代碼路徑，傳入請求可以采用這些路徑：
用戶代碼路徑：用戶正在從他們的瀏覽器使用應(yīng)用程序。瀏覽器向 Web 控制器發(fā)送請求，控制器調(diào)用領(lǐng)域代碼。
第三方系統(tǒng)代碼路徑：應(yīng)用程序的 HTTP API 也從第三方系統(tǒng)調(diào)用。在這個例子中，第三方系統(tǒng)調(diào)用與用戶瀏覽器相同的 web 控制器。
計(jì)時(shí)器代碼路徑：與許多應(yīng)用程序一樣，此應(yīng)用程序有一些由計(jì)時(shí)器觸發(fā)的計(jì)劃任務(wù)。
這些代碼路徑中的每一個都可以具有不同的特征。域服務(wù)涉及所有三個代碼路徑。在涉及域服務(wù)錯誤的事件期間，了解導(dǎo)致錯誤的代碼路徑將大有幫助！
如果我們不知道代碼路徑，我們很容易在事件調(diào)查期間做出毫無結(jié)果的猜測。
所以，我們應(yīng)該將代碼路徑添加到日志中！以下是我們?nèi)绾问褂?Spring Boot 做到這一點(diǎn)。
為傳入的 Web 請求添加代碼路徑
在 Java 中，SLF4J 日志庫提供了?MDC?類（消息診斷上下文）。這個類允許我們向在同一線程中發(fā)出的所有日志事件添加自定義字段。
要為每個傳入的 Web 請求添加自定義字段，我們需要構(gòu)建一個攔截器，在每個請求的開頭添加?codePath?字段，甚至在我們的 Web 控制器代碼執(zhí)行之前。
我們可以通過實(shí)現(xiàn)?HandlerInterceptor?接口來做到這一點(diǎn)：
public class LoggingInterceptor implements HandlerInterceptor { ? ?
? ?public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
? ? ? ? ? ?throws Exception { ? ? ? ?if (request.getHeader("X-CUSTOM-HEADER") != null) {
? ? ? ? ? ?MDC.put("codePath", "3rdParty");
? ? ? ?} else {
? ? ? ? ? ?MDC.put("codePath", "user");
? ? ? ?} ? ? ? ?return true;
? ?} ? ?
? ?public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
? ? ? ? ? ?ModelAndView modelAndView) {
? ? ? ?MDC.remove("codePath");
? ?}
}
在?preHandle()?方法中，我們調(diào)用?MDC.put()?將?codePath?字段添加到所有日志事件中。如果請求包含標(biāo)識請求來自第三方方系統(tǒng)的標(biāo)頭，我們將代碼路徑設(shè)置為?3rdParty，否則，我們假設(shè)請求來自用戶的瀏覽器。
根據(jù)應(yīng)用的不同，這里的邏輯可能會有很大的不同，當(dāng)然，這只是一個例子。
在?postHandle()?方法中，我們不應(yīng)該忘記調(diào)用?MDC.remove()?再次刪除所有先前設(shè)置的字段，否則線程仍會保留這些字段，即使它返回到線程池，以及下一個請求 由該線程提供服務(wù)的那些字段可能仍然設(shè)置為錯誤的值。
要激活攔截器，我們需要將其添加到?InterceptorRegistry?中：
class WebConfigurer implements WebMvcConfigurer { ? ?
? ?public void addInterceptors(InterceptorRegistry registry) {
? ? ? ?registry.addInterceptor(new LoggingInterceptor());
? ?}
}
就是這樣。在傳入日志事件的線程中發(fā)出的所有日志事件現(xiàn)在都具有?codePath?字段。
如果任何請求創(chuàng)建并啟動子線程，請確保在新線程生命周期開始時(shí)調(diào)用?MDC.put()。
在計(jì)劃作業(yè)中添加代碼路徑
在 Spring Boot 中，我們可以通過使用?@Scheduled?和?@EnableScheduling?注解輕松創(chuàng)建計(jì)劃作業(yè)。
要將代碼路徑添加到日志中，我們需要確保調(diào)用?MDC.put()?作為調(diào)度方法中的第一件事：
class Timer { ? ?private final DomainService domainService; ? ?private static final Logger logger = LoggerFactory.getLogger(Timer.class); ? ?public Timer(DomainService domainService) { ? ? ? ?this.domainService = domainService;
? ?} ? ?(fixedDelay = 5000) ? ?void scheduledHello() {
? ? ? ?MDC.put("codePath", "timer");
? ? ? ?logger.info("log event from timer"); ? ? ? ?// do some actual work
? ? ? ?MDC.remove("codePath");
? ?}
}
這樣，從執(zhí)行調(diào)度方法的線程發(fā)出的所有日志事件都將包含字段?codePath。我們也可以創(chuàng)建我們自己的?@Job?注解或類似的注解來為我們完成這項(xiàng)工作，但這超出了本文的范圍。
為了使預(yù)定作業(yè)的日志更有價(jià)值，我們可以添加其他字段：
job_status：指示作業(yè)是否成功的狀態(tài)。
job_id：已執(zhí)行作業(yè)的 ID。
job_records_processed：如果作業(yè)進(jìn)行一些批處理，它可以記錄處理的記錄數(shù)。
......
通過日志中的這些字段，我們可以在日志服務(wù)器獲取到很多有用的信息！
將用戶 ID 添加到用戶啟動的日志事件
典型 Web 應(yīng)用程序中的大部分工作是在來自用戶瀏覽器的 Web 請求中完成的，這些請求會觸發(fā)應(yīng)用程序中的線程，為瀏覽器創(chuàng)建響應(yīng)。
想象一下發(fā)生了一些錯誤，日志中的堆棧跟蹤顯示它與特定的用戶配置有關(guān)。但是我們不知道請求來自哪個用戶！
為了緩解這種情況，在用戶觸發(fā)的所有日志事件中包含某種用戶 ID 是非常有幫助的。
由于我們知道傳入的 Web 請求大多直接來自用戶的瀏覽器，因此我們可以在創(chuàng)建的同一個?LoggingInterceptor?中添加?username?字段以添加?codePath?字段：
public class LoggingInterceptor implements HandlerInterceptor { ? ?
? ?public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler)
? ? ? ? ? ?throws Exception {
? ? ? ?Object principal = SecurityContextHolder.getContext().getAuthentication().getPrincipal(); ? ? ? ?if (principal instanceof UserDetails) {
? ? ? ? ? ?String username = ((UserDetails) principal).getUsername();
? ? ? ? ? ?MDC.put("username", username);
? ? ? ?} else {
? ? ? ? ? ?String username = principal.toString();
? ? ? ? ? ?MDC.put("username", username);
? ? ? ?} ? ? ? ?return true;
? ?} ? ?
? ?public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler,
? ? ? ? ? ?ModelAndView modelAndView) {
? ? ? ?MDC.remove("username");
? ?}
}
這段代碼假設(shè)我們使用 Spring Security 來管理對 Web 應(yīng)用程序的訪問。我們使用?SecurityContextHolder?來獲取?Principal?并從中提取用戶名以將其傳遞給?MDC.put()。
從服務(wù)請求的線程發(fā)出的每個日志事件現(xiàn)在都將包含用戶名字段和用戶名。
有了這個字段，我們現(xiàn)在可以過濾特定用戶請求的日志。如果用戶報(bào)告了問題，我們可以根據(jù)他們的姓名過濾日志，并極大地減少我們必須查看的日志。
根據(jù)規(guī)定，您可能希望記錄更不透明的用戶 ID 而不是用戶名。
為錯誤日志事件添加根本原因
當(dāng)我們的應(yīng)用程序出現(xiàn)錯誤時(shí)，我們通常會記錄堆棧跟蹤。堆棧跟蹤幫助我們確定錯誤的根本原因。如果沒有堆棧跟蹤，我們將不知道是哪個代碼導(dǎo)致了錯誤！
但是，如果我們想在應(yīng)用程序中運(yùn)行錯誤統(tǒng)計(jì)信息，堆棧跟蹤是非常笨拙的。假設(shè)我們想知道我們的應(yīng)用程序每天總共記錄了多少錯誤，以及其中有多少是由哪個根本原因異常引起的。我們必須從日志中導(dǎo)出所有堆棧跟蹤，并對它們進(jìn)行一些手動過濾，才能得到該問題的答案！
但是，如果我們將自定義字段?rootCause?添加到每個錯誤日志事件，我們可以通過該字段過濾日志事件，然后在日志服務(wù)器的 UI 中創(chuàng)建不同根本原因的直方圖或餅圖，甚至無需導(dǎo)出數(shù)據(jù)。
在 Spring Boot 中執(zhí)行此操作的一種方法是創(chuàng)建一個?@ExceptionHandle：
class WebExceptionHandler { ? ?private static final Logger logger = LoggerFactory.getLogger(WebExceptionHandler.class);
? ?
? ?
? ?public void internalServerError(Exception e) {
? ? ? ?MDC.put("rootCause", getRootCause(e).getClass().getName());
? ? ? ?logger.error("returning 500 (internal server error).", e);
? ? ? ?MDC.remove("rootCause");
? ?} ? ?private Throwable getRootCause(Exception e) {
? ? ? ?Throwable rootCause = e; ? ? ? ?while (e.getCause() != null && rootCause.getCause() != rootCause) {
? ? ? ? ? ?rootCause = e.getCause();
? ? ? ?} ? ? ? ?return rootCause;
? ?}
}
我們創(chuàng)建了一個用?@ControllerAdvice?注解的類，這意味著它在我們所有的 web 控制器中都是有效的。
在類中，我們創(chuàng)建了一個用?@ExceptionHandler?注解的方法。對于任何 Web 控制器中出現(xiàn)的異常，都會調(diào)用此方法。它將?rootCause?MDC 字段設(shè)置為導(dǎo)致錯誤的異常類的完全限定名稱，然后記錄異常的堆棧跟蹤。
就是這樣。所有打印堆棧跟蹤的日志事件現(xiàn)在都有一個字段?rootCause，我們可以通過這個字段進(jìn)行過濾以了解我們應(yīng)用程序中的錯誤分布。
向所有日志事件添加跟蹤 ID
如果我們運(yùn)行多個服務(wù)，例如在微服務(wù)環(huán)境中，分析錯誤時(shí)事情會很快變得復(fù)雜。一個服務(wù)調(diào)用另一個服務(wù)，另一個服務(wù)調(diào)用再一個服務(wù)，并且很難（如果可能的話）跟蹤一個服務(wù)中的錯誤到另一個服務(wù)中的錯誤。
跟蹤 ID 有助于連接一個服務(wù)中的日志事件和另一個服務(wù)中的日志事件：
在上面的示例圖中，服務(wù) 1 被調(diào)用并生成跟蹤 ID“1234”。然后它調(diào)用服務(wù) 2 和 3，將相同的跟蹤 ID 傳播給它們，以便它們可以將相同的跟蹤 ID 添加到其日志事件中，從而可以通過搜索特定的跟蹤 ID 來連接所有服務(wù)的日志事件。
對于每個傳出請求，服務(wù) 1 還會創(chuàng)建一個唯一的“跨度 ID”。雖然跟蹤跨越服務(wù) 1 的整個請求/響應(yīng)周期，但跨度僅跨越一個服務(wù)和另一個服務(wù)之間的請求/響應(yīng)周期。
我們可以自己實(shí)現(xiàn)這樣的跟蹤機(jī)制，但是有一些跟蹤標(biāo)準(zhǔn)和工具可以使用這些標(biāo)準(zhǔn)集成到跟蹤系統(tǒng)中，例如?Logz.io 的分布式跟蹤功能。
我們還是使用標(biāo)準(zhǔn)工具吧。在 Spring Boot 世界中，這就是?Spring Cloud Sleuth，我們可以通過簡單地將它添加到我們的?pom.xml，從而把該功能集成到我們的應(yīng)用程序中：
<dependencyManagement>
?<dependencies>
? ?<dependency>
? ? ?<groupId>org.springframework.cloud</groupId>
? ? ?<artifactId>spring-cloud-dependencies</artifactId>
? ? ?<version>2020.0.3</version>
? ? ?<type>pom</type>
? ? ?<scope>import</scope>
? ?</dependency>
?</dependencies></dependencyManagement><dependencies>
?<dependency>
? ?<groupId>org.springframework.cloud</groupId>
? ?<artifactId>spring-cloud-starter-sleuth</artifactId>
?</dependency></dependencies>
這會自動將跟蹤和跨度 ID 添加到我們的日志中，并在使用支持的 HTTP 客戶端時(shí)通過請求標(biāo)頭將它們從一個服務(wù)傳播到下一個服務(wù)。您可以在“使用 Spring Cloud Sleuth 在分布式系統(tǒng)中進(jìn)行跟蹤”一文中閱讀有關(guān) Spring Cloud Sleuth 的更多信息。
添加某些代碼路徑的持續(xù)時(shí)間
我們的應(yīng)用程序響應(yīng)請求所需的總持續(xù)時(shí)間是一個重要的指標(biāo)。如果速度太慢，用戶會感到沮喪。
通常，將請求持續(xù)時(shí)間作為指標(biāo)公開并創(chuàng)建顯示請求持續(xù)時(shí)間的直方圖和百分位數(shù)的儀表板是一個好主意，這樣我們就可以一目了然地了解應(yīng)用程序的健康狀況，甚至可能在違反某個閾值時(shí)收到警報(bào)。
然而，我們并不是一直在查看儀表板，我們可能不僅對總請求持續(xù)時(shí)間感興趣，而且對某些代碼路徑的持續(xù)時(shí)間感興趣。在分析日志以調(diào)查問題時(shí)，了解代碼中特定路徑執(zhí)行所需的時(shí)間可能是一個重要線索。
在 Java 中，我們可能會這樣做：
void callThirdPartyService() throws InterruptedException {
? ?logger.info("log event from the domain service");
? ?Instant start=Instant.now();
? ?Thread.sleep(2000); // simulating an expensive operation
? ?Duration duration=Duration.between(start,Instant.now());
? ?MDC.put("thirdPartyCallDuration",String.valueOf(duration.getNano()));
? ?logger.info("call to third-party service successful!");
? ?MDC.remove("thirdPartyCallDuration");
}
假設(shè)我們正在調(diào)用第三方服務(wù)并希望將持續(xù)時(shí)間添加到日志中。使用?Instant.now()?和?Duration.between()，我們計(jì)算持續(xù)時(shí)間，將其添加到 MDC，然后創(chuàng)建日志事件。
這個日志事件現(xiàn)在將包含字段?thirdPartyCallDuration，我們可以在日志中過濾和搜索該字段。 例如，我們可能會搜索這個調(diào)用耗時(shí)過長的實(shí)例。 然后，我們可以使用用戶 ID 或跟蹤 ID，當(dāng)這需要特別長的時(shí)間時(shí)，我們也可以將它們作為日志事件的字段來找出模式。
在Logz.io中查詢結(jié)構(gòu)化日志
如果我們按照關(guān)于?per-environment logging?的文章中的描述設(shè)置了日志記錄到?Logz.io，我們現(xiàn)在可以在 Logz.io 提供的 Kibana UI 中查詢?nèi)罩尽?/p>
錯誤分布
例如，我們可以查詢在?rootCause?字段中具有值的所有日志事件：
__exists__: "rootCause"
這將顯示具有根本原因的錯誤事件列表。
我們還可以在 Logz.io UI 中創(chuàng)建一個可視化來顯示給定時(shí)間范圍內(nèi)的錯誤分布：
此圖表顯示幾乎一半的錯誤是由?ThingyException?引起的，因此檢查是否可以以某種方式避免此異?？赡苁莻€好主意。如果無法避免，我們應(yīng)該將其記錄在?WARN?而不是?ERROR?上，以保持錯誤日志的清潔。
跨代碼路徑的錯誤分布
例如，假設(shè)用戶抱怨預(yù)定的作業(yè)沒有正常工作。如果我們在調(diào)度方法代碼中添加了一個?job_status?字段，我們可以通過那些失敗的作業(yè)來過濾日志：
job_status: "ERROR"
為了獲得更高級的視圖，我們可以創(chuàng)建另一個餅圖可視化，顯示?job_status?和?rootCause?的分布：
我們現(xiàn)在可以看到大部分預(yù)定的作業(yè)都失敗了！我們應(yīng)該為此添加一些警報(bào)！ 我們還可以查看哪些異常是大多數(shù)計(jì)劃作業(yè)的根本原因并開始調(diào)查。
檢查用戶的錯誤
或者，假設(shè)用戶名為 “user” 的用戶提出了一個支持請求，指定了它發(fā)生的大致日期和時(shí)間。我們可以使用查詢?username: user?過濾日志以僅顯示該用戶的日志，并且可以快速將用戶問題的原因歸零。
我們還可以擴(kuò)展查詢以僅顯示具有?rootCause?的該用戶的日志事件，以直接了解何時(shí)出了什么問題。
username: "user" AND _exists_: "rootCause"
結(jié)構(gòu)化您的日志
本文僅展示了幾個示例，說明我們?nèi)绾蜗蛉罩臼录砑咏Y(jié)構(gòu)并在查詢?nèi)罩緯r(shí)使用該結(jié)構(gòu)。以后可以在日志中搜索的任何內(nèi)容都應(yīng)該是日志事件中的自定義字段。添加到日志事件中的字段在很大程度上取決于我們正在構(gòu)建的應(yīng)用程序，所以在編寫代碼時(shí)，一定要考慮哪些信息可以幫助您分析日志。
您可以在?GitHub 上（
https://github.com/thombergs/code-examples/tree/master/logging/structured-logging）找到本文中討論的代碼示例。
